[==========] 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:14.647033 32752 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.252.62:43707
I20260812 06:18:14.647913 32752 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:14.648447 32752 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.654455 32766 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:14.654562   302 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:14.654430 32752 server_base.cc:1061] running on GCE node
W20260812 06:18:14.654626 32763 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.655102 32752 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.655191 32752 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:14.655241 32752 hybrid_clock.cc:648] HybridClock initialized: now 1786515494655239 us; error 0 us; skew 500 ppm
I20260812 06:18:14.656811 32752 webserver.cc:533] Webserver started at http://127.31.252.62:37601/ using document root <none> and password file <none>
I20260812 06:18:14.657292 32752 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.657347 32752 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.657549 32752 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.659078 32752 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/master-0-root/instance:
uuid: "3849ee3c32f741ffa74cdca3b9cd6602"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-bqcl"
I20260812 06:18:14.662214 32752 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:14.664047   308 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:14.664913 32752 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:14.665015 32752 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/master-0-root
uuid: "3849ee3c32f741ffa74cdca3b9cd6602"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-bqcl"
I20260812 06:18:14.665100 32752 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-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:14.687888 32752 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.688494 32752 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:14.688671 32752 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.695622 32752 rpc_server.cc:307] RPC server started. Bound to: 127.31.252.62:43707
I20260812 06:18:14.695624   406 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.252.62:43707 every 8 connection(s)
I20260812 06:18:14.698187   409 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:14.704653   409 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: Bootstrap starting.
I20260812 06:18:14.707003   409 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.707788   409 log.cc:826] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:14.709254   409 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: No bootstrap required, opened a new log
I20260812 06:18:14.711814   409 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER }
I20260812 06:18:14.711962   409 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.712014   409 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3849ee3c32f741ffa74cdca3b9cd6602, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.712545   409 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [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: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER }
I20260812 06:18:14.712683   409 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.712728   409 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.712812   409 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.713470   409 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER }
I20260812 06:18:14.713824   409 leader_election.cc:304] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [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: 3849ee3c32f741ffa74cdca3b9cd6602; no voters: 
I20260812 06:18:14.714072   409 leader_election.cc:290] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.714226   413 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.714444   413 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 1 LEADER]: Becoming Leader. State: Replica: 3849ee3c32f741ffa74cdca3b9cd6602, State: Running, Role: LEADER
I20260812 06:18:14.714771   413 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [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: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER }
I20260812 06:18:14.714951   409 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.716389   417 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3849ee3c32f741ffa74cdca3b9cd6602. Latest consensus state: current_term: 1 leader_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER } }
I20260812 06:18:14.716389   415 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3849ee3c32f741ffa74cdca3b9cd6602" member_type: VOTER } }
I20260812 06:18:14.716531   415 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.716531   417 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.716962 32752 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:14.718904   434 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:14.718979   434 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:14.719044   431 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.719895   431 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.724074   431 catalog_manager.cc:1383] Generated new cluster ID: 0e90e921f1f44c909424310f758917f0
I20260812 06:18:14.724172   431 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:14.733218   431 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:14.733903   431 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:14.745509   431 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: Generated new TSK 0
I20260812 06:18:14.746002   431 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:14.749334 32752 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.751672   457 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:14.751725   446 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:14.751766   449 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:14.752013 32752 server_base.cc:1061] running on GCE node
I20260812 06:18:14.752166 32752 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.752209 32752 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:14.752235 32752 hybrid_clock.cc:648] HybridClock initialized: now 1786515494752235 us; error 0 us; skew 500 ppm
I20260812 06:18:14.753041 32752 webserver.cc:533] Webserver started at http://127.31.252.1:32867/ using document root <none> and password file <none>
I20260812 06:18:14.753191 32752 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.753239 32752 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.753309 32752 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.753625 32752 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/instance:
uuid: "e9277292877b4e629d48281327fc7e03"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-bqcl"
I20260812 06:18:14.755002 32752 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:14.755892   463 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:14.756098 32752 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:14.756165 32752 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root
uuid: "e9277292877b4e629d48281327fc7e03"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-bqcl"
I20260812 06:18:14.756227 32752 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-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:14.771224 32752 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.771587 32752 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.772006 32752 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:14.772810 32752 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:14.772861 32752 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.772904 32752 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:14.772934 32752 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.779033 32752 rpc_server.cc:307] RPC server started. Bound to: 127.31.252.1:34767
I20260812 06:18:14.779081   589 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.252.1:34767 every 8 connection(s)
I20260812 06:18:14.791280   595 heartbeater.cc:344] Connected to a master server at 127.31.252.62:43707
I20260812 06:18:14.791504   595 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:14.791903   595 heartbeater.cc:507] Master 127.31.252.62:43707 requested a full tablet report, sending...
I20260812 06:18:14.793258   339 ts_manager.cc:194] Registered new tserver with Master: e9277292877b4e629d48281327fc7e03 (127.31.252.1:34767)
I20260812 06:18:14.793988 32752 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014383652s
I20260812 06:18:14.794427   339 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55820
I20260812 06:18:14.803012   339 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55834:
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:14.815707   528 tablet_service.cc:1511] Processing CreateTablet for tablet a4cb6f1487b54085a112e6baf87e433f (DEFAULT_TABLE table=heavy-update-compaction-test [id=01931004f43f4ba384a1651d1a2475d1]), partition=
I20260812 06:18:14.816145   528 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a4cb6f1487b54085a112e6baf87e433f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.818410   614 tablet_bootstrap.cc:492] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Bootstrap starting.
I20260812 06:18:14.819465   614 tablet_bootstrap.cc:654] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.820647   614 tablet_bootstrap.cc:492] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: No bootstrap required, opened a new log
I20260812 06:18:14.820741   614 ts_tablet_manager.cc:1403] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:14.821175   614 raft_consensus.cc:359] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9277292877b4e629d48281327fc7e03" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34767 } }
I20260812 06:18:14.821295   614 raft_consensus.cc:385] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.821333   614 raft_consensus.cc:740] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e9277292877b4e629d48281327fc7e03, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.821457   614 consensus_queue.cc:260] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [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: "e9277292877b4e629d48281327fc7e03" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34767 } }
I20260812 06:18:14.821552   614 raft_consensus.cc:399] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.821593   614 raft_consensus.cc:493] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.821640   614 raft_consensus.cc:3060] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.822587   614 raft_consensus.cc:515] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9277292877b4e629d48281327fc7e03" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34767 } }
I20260812 06:18:14.822726   614 leader_election.cc:304] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [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: e9277292877b4e629d48281327fc7e03; no voters: 
I20260812 06:18:14.822903   614 leader_election.cc:290] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.823175   614 ts_tablet_manager.cc:1434] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:14.823189   620 raft_consensus.cc:2804] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.823642   595 heartbeater.cc:499] Master 127.31.252.62:43707 was elected leader, sending a full tablet report...
I20260812 06:18:14.824010   620 raft_consensus.cc:697] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 1 LEADER]: Becoming Leader. State: Replica: e9277292877b4e629d48281327fc7e03, State: Running, Role: LEADER
I20260812 06:18:14.824162   620 consensus_queue.cc:237] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [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: "e9277292877b4e629d48281327fc7e03" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34767 } }
I20260812 06:18:14.826650   339 catalog_manager.cc:5719] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 reported cstate change: term changed from 0 to 1, leader changed from <none> to e9277292877b4e629d48281327fc7e03 (127.31.252.1). New cstate: current_term: 1 leader_uuid: "e9277292877b4e629d48281327fc7e03" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9277292877b4e629d48281327fc7e03" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34767 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:14.899688 32752 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.021s	sys 0.013s
I20260812 06:18:15.030019   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f): perf score=19.054940
I20260812 06:18:15.167330   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.137s	user 0.101s	sys 0.034s Metrics: {"bytes_written":8697369,"cfile_init":1,"compiler_manager_pool.queue_time_us":228,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":981,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33871,"lbm_writes_lt_1ms":669,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":32128,"thread_start_us":128,"threads_started":1,"update_count":1060}
I20260812 06:18:15.168299   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling LogGCOp(a4cb6f1487b54085a112e6baf87e433f): free 20743880 bytes of WAL
I20260812 06:18:15.168563   472 log_reader.cc:385] T a4cb6f1487b54085a112e6baf87e433f: removed 2 log segments from log reader
I20260812 06:18:15.168622   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000001 (ops 1-6)
I20260812 06:18:15.168678   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000002 (ops 7-11)
I20260812 06:18:15.172469   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: LogGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:15.172755   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f): 16411393 bytes on disk
I20260812 06:18:15.173262   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.173731   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:15.189587   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5457,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:18:15.190058   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:15.297485   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.107s	user 0.081s	sys 0.017s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569852,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":427,"lbm_read_time_us":5716,"lbm_reads_lt_1ms":360,"lbm_write_time_us":17733,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":291,"threads_started":5,"update_count":1500}
I20260812 06:18:15.297957   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:15.336305   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.038s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.336825   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:15.432256   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.095s	user 0.087s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":762,"lbm_read_time_us":6659,"lbm_reads_lt_1ms":363,"lbm_write_time_us":16693,"lbm_writes_lt_1ms":343,"mutex_wait_us":16,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":1500}
I20260812 06:18:15.432719   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:15.471343   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14969,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.471764   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:15.481168   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.481559   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:15.593230   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.112s	user 0.104s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":776,"lbm_read_time_us":8075,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19948,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:18:15.593690   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:15.635782   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.042s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14666,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.636236   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:15.645679   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.009s	user 0.004s	sys 0.004s 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:15.646061   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:15.763211   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.117s	user 0.084s	sys 0.033s 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":217,"lbm_read_time_us":7895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22524,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:18:15.763675   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:15.803133   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.039s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13335,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.803644   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:15.813441   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3610,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.813954   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:15.936980   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.123s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":9013,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21232,"lbm_writes_lt_1ms":443,"mutex_wait_us":235,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:15.937517   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:15.980935   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.043s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12433,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.981539   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:15.991827   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.992326   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:16.144222   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.152s	user 0.117s	sys 0.023s 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":492,"lbm_read_time_us":10794,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20997,"lbm_writes_lt_1ms":443,"mutex_wait_us":250,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:16.144783   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:16.191602   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.047s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20240,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.192063   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.201926   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.202450   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:16.325976   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.123s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":591,"lbm_read_time_us":7765,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24556,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:16.326527   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:16.361720   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.035s	user 0.027s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12587,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.362313   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.378588   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.379097   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:16.407435   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1264,"drs_written":1,"lbm_read_time_us":67,"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:16.408236   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling LogGCOp(a4cb6f1487b54085a112e6baf87e433f): free 121006434 bytes of WAL
I20260812 06:18:16.408458   472 log_reader.cc:385] T a4cb6f1487b54085a112e6baf87e433f: removed 12 log segments from log reader
I20260812 06:18:16.408512   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000003 (ops 12-16)
I20260812 06:18:16.408547   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000004 (ops 17-21)
I20260812 06:18:16.408586   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000005 (ops 22-26)
I20260812 06:18:16.408627   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000006 (ops 27-31)
I20260812 06:18:16.408665   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000007 (ops 32-36)
I20260812 06:18:16.408703   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000008 (ops 37-41)
I20260812 06:18:16.408740   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000009 (ops 42-46)
I20260812 06:18:16.408778   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000010 (ops 47-50)
I20260812 06:18:16.408816   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000011 (ops 51-55)
I20260812 06:18:16.408855   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000012 (ops 56-60)
I20260812 06:18:16.408885   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000013 (ops 61-65)
I20260812 06:18:16.408922   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000014 (ops 66-70)
I20260812 06:18:16.430331   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: LogGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:16.430757   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f): 472 bytes on disk
I20260812 06:18:16.431171   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.431727   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=3.181125
I20260812 06:18:16.446099   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.014s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:16.446475   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.455233   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3253,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.455585   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:16.611800   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.156s	user 0.118s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":856,"lbm_read_time_us":10747,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32848,"lbm_writes_lt_1ms":643,"mutex_wait_us":17,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:16.612339   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=11.118625
I20260812 06:18:16.650985   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.038s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15161,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:16.651533   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.670198   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6029,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.670681   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.679431   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.679960   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:16.840368   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.160s	user 0.127s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":119,"lbm_read_time_us":11441,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30190,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:18:16.840894   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:16.887844   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.047s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21257,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.888383   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:16.900978   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.901410   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:17.072073   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.170s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":10529,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29364,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35072,"update_count":2500}
I20260812 06:18:17.072564   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:17.131055   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.058s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22450,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.131520   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:17.141322   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.141932   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:17.299007   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.157s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":116,"lbm_read_time_us":11015,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26099,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:18:17.299608   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:17.352375   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.053s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20293,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.352834   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:17.362769   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.363265   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:17.526139   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.163s	user 0.127s	sys 0.032s 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":507,"lbm_read_time_us":11915,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25872,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:18:17.526621   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:17.580031   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.053s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.580575   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:17.590306   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.590755   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:17.736194   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.145s	user 0.086s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":10580,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23939,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:17.736769   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=10.126437
I20260812 06:18:17.764940   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.028s	user 0.013s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11883,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.765524   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:17.776439   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.777117   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:17.817329   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.040s	user 0.031s	sys 0.006s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1318,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1553,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:17.818231   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling LogGCOp(a4cb6f1487b54085a112e6baf87e433f): free 124257245 bytes of WAL
I20260812 06:18:17.818466   472 log_reader.cc:385] T a4cb6f1487b54085a112e6baf87e433f: removed 12 log segments from log reader
I20260812 06:18:17.818518   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000015 (ops 71-75)
I20260812 06:18:17.818558   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000016 (ops 76-80)
I20260812 06:18:17.818593   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000017 (ops 81-85)
I20260812 06:18:17.818619   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000018 (ops 86-90)
I20260812 06:18:17.818663   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000019 (ops 91-95)
I20260812 06:18:17.818697   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000020 (ops 96-100)
I20260812 06:18:17.818729   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000021 (ops 101-105)
I20260812 06:18:17.818760   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000022 (ops 106-110)
I20260812 06:18:17.818791   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000023 (ops 111-115)
I20260812 06:18:17.818822   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000024 (ops 116-120)
I20260812 06:18:17.818852   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000025 (ops 121-124)
I20260812 06:18:17.818883   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000026 (ops 125-129)
I20260812 06:18:17.839579   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: LogGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:17.840075   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f): 483 bytes on disk
I20260812 06:18:17.840663   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f) 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:17.841571   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=3.181125
I20260812 06:18:17.855552   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.014s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:18:17.855971   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling LogGCOp(a4cb6f1487b54085a112e6baf87e433f): free 12017954 bytes of WAL
I20260812 06:18:17.856161   472 log_reader.cc:385] T a4cb6f1487b54085a112e6baf87e433f: removed 1 log segments from log reader
I20260812 06:18:17.856204   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000027 (ops 130-134)
I20260812 06:18:17.858053   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: LogGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:17.858342   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:18.021413   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.163s	user 0.099s	sys 0.062s Metrics: {"cfile_cache_miss":540,"cfile_cache_miss_bytes":25061982,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":212,"lbm_read_time_us":9790,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28774,"lbm_writes_lt_1ms":550,"mutex_wait_us":27,"peak_mem_usage":63403145,"reinsert_count":0,"spinlock_wait_cycles":61952,"thread_start_us":67,"threads_started":1,"update_count":2535}
I20260812 06:18:18.021945   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:18.062023   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.040s	user 0.021s	sys 0.012s Metrics: {"bytes_written":16122737,"delete_count":0,"lbm_write_time_us":15730,"lbm_writes_lt_1ms":396,"reinsert_count":0,"update_count":1965}
I20260812 06:18:18.062515   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:18.074008   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.074518   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:18.251893   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.177s	user 0.104s	sys 0.064s Metrics: {"cfile_cache_miss":525,"cfile_cache_miss_bytes":24487524,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":9535,"lbm_reads_lt_1ms":565,"lbm_write_time_us":31777,"lbm_writes_lt_1ms":536,"mutex_wait_us":24,"peak_mem_usage":61788271,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2465}
I20260812 06:18:18.252489   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:18.302627   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22263,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.303190   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:18.314604   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.315173   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:18.480077   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.165s	user 0.116s	sys 0.035s 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":170,"lbm_read_time_us":10225,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30736,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:18.480746   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:18.527086   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.046s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.527644   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:18.537868   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.538496   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:18.671371   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.133s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":8591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25369,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:18.672052   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=11.118625
I20260812 06:18:18.699023   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11020,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.699550   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:18.718397   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.718859   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:18.849766   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.131s	user 0.089s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":337,"lbm_read_time_us":9287,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23168,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35584,"update_count":2000}
I20260812 06:18:18.850383   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=11.118625
I20260812 06:18:18.890935   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.040s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14582,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.891363   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:18.907032   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.016s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5089,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.907533   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:19.047312   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.140s	user 0.090s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":7843,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22600,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:18:19.047876   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:19.094421   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.046s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19177,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.094955   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:19.109167   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.109736   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:19.143437   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushMRSOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.034s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1090,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1325,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.144191   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling LogGCOp(a4cb6f1487b54085a112e6baf87e433f): free 112239561 bytes of WAL
I20260812 06:18:19.144428   472 log_reader.cc:385] T a4cb6f1487b54085a112e6baf87e433f: removed 11 log segments from log reader
I20260812 06:18:19.144479   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000028 (ops 135-139)
I20260812 06:18:19.144515   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000029 (ops 140-144)
I20260812 06:18:19.144537   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000030 (ops 145-149)
I20260812 06:18:19.144560   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000031 (ops 150-154)
I20260812 06:18:19.144591   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000032 (ops 155-159)
I20260812 06:18:19.144622   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000033 (ops 160-164)
I20260812 06:18:19.144649   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000034 (ops 165-169)
I20260812 06:18:19.144680   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000035 (ops 170-174)
I20260812 06:18:19.144711   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000036 (ops 175-178)
I20260812 06:18:19.144740   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000037 (ops 179-183)
I20260812 06:18:19.144770   472 log.cc:1079] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/a4cb6f1487b54085a112e6baf87e433f/wal-000000038 (ops 184-188)
I20260812 06:18:19.164633   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: LogGCOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.020s	user 0.003s	sys 0.015s Metrics: {}
I20260812 06:18:19.165143   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f): 462 bytes on disk
I20260812 06:18:19.165632   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: UndoDeltaBlockGCOp(a4cb6f1487b54085a112e6baf87e433f) 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:19.166251   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=3.181125
I20260812 06:18:19.186859   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.020s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:19.187331   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=2.188937
I20260812 06:18:19.200058   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4928,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.200512   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:19.383942 32752 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.484s	user 1.643s	sys 0.113s
I20260812 06:18:19.408699   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.208s	user 0.139s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13681,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35864,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:18:19.409286   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f): perf score=14.095187
I20260812 06:18:19.456948   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: FlushDeltaMemStoresOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.047s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22178,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.457383   597 maintenance_manager.cc:419] P e9277292877b4e629d48281327fc7e03: Scheduling MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f): perf score=1.000000
I20260812 06:18:19.511507 32752 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.127s	user 0.002s	sys 0.000s
I20260812 06:18:19.512128 32752 tablet_server.cc:179] TabletServer@127.31.252.1:0 shutting down...
I20260812 06:18:19.577349   472 maintenance_manager.cc:643] P e9277292877b4e629d48281327fc7e03: MajorDeltaCompactionOp(a4cb6f1487b54085a112e6baf87e433f) complete. Timing: real 0.120s	user 0.096s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":250,"lbm_read_time_us":8110,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23899,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":88,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.578022 32752 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:19.580942 32752 tablet_replica.cc:333] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03: stopping tablet replica
I20260812 06:18:19.581182 32752 raft_consensus.cc:2243] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.581480 32752 raft_consensus.cc:2272] T a4cb6f1487b54085a112e6baf87e433f P e9277292877b4e629d48281327fc7e03 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.586997 32752 tablet_server.cc:196] TabletServer@127.31.252.1:0 shutdown complete.
I20260812 06:18:19.629644 32752 master.cc:562] Master@127.31.252.62:43707 shutting down...
I20260812 06:18:19.634312 32752 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.634491 32752 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.634560 32752 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3849ee3c32f741ffa74cdca3b9cd6602: stopping tablet replica
I20260812 06:18:19.815294 32752 master.cc:584] Master@127.31.252.62:43707 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5240 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:19.899698 32752 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.252.62:39443
I20260812 06:18:19.900098 32752 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.902038   650 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:19.902171   653 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:19.902244 32752 server_base.cc:1061] running on GCE node
W20260812 06:18:19.902045   651 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:19.902477 32752 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.902524 32752 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:19.902539 32752 hybrid_clock.cc:648] HybridClock initialized: now 1786515499902538 us; error 0 us; skew 500 ppm
I20260812 06:18:19.903306 32752 webserver.cc:533] Webserver started at http://127.31.252.62:42175/ using document root <none> and password file <none>
I20260812 06:18:19.903426 32752 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.903465 32752 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.903523 32752 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.903872 32752 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/master-0-root/instance:
uuid: "805e27d9c46643919ae53b84396ae193"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-bqcl"
I20260812 06:18:19.905215 32752 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:19.906080   667 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:19.906308 32752 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:19.906378 32752 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/master-0-root
uuid: "805e27d9c46643919ae53b84396ae193"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-bqcl"
I20260812 06:18:19.906443 32752 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-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:19.922544 32752 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.922863 32752 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.927079 32752 rpc_server.cc:307] RPC server started. Bound to: 127.31.252.62:39443
I20260812 06:18:19.927100   745 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.252.62:39443 every 8 connection(s)
I20260812 06:18:19.927839   748 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:19.929431   748 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193: Bootstrap starting.
I20260812 06:18:19.930146   748 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:19.931032   748 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193: No bootstrap required, opened a new log
I20260812 06:18:19.931382   748 raft_consensus.cc:359] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805e27d9c46643919ae53b84396ae193" member_type: VOTER }
I20260812 06:18:19.931460   748 raft_consensus.cc:385] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:19.931483   748 raft_consensus.cc:740] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 805e27d9c46643919ae53b84396ae193, State: Initialized, Role: FOLLOWER
I20260812 06:18:19.931638   748 consensus_queue.cc:260] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [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: "805e27d9c46643919ae53b84396ae193" member_type: VOTER }
I20260812 06:18:19.931707   748 raft_consensus.cc:399] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:19.931741   748 raft_consensus.cc:493] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:19.931789   748 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:19.932394   748 raft_consensus.cc:515] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805e27d9c46643919ae53b84396ae193" member_type: VOTER }
I20260812 06:18:19.932518   748 leader_election.cc:304] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [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: 805e27d9c46643919ae53b84396ae193; no voters: 
I20260812 06:18:19.932684   748 leader_election.cc:290] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:19.932778   751 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:19.933009   751 raft_consensus.cc:697] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 1 LEADER]: Becoming Leader. State: Replica: 805e27d9c46643919ae53b84396ae193, State: Running, Role: LEADER
I20260812 06:18:19.933079   748 sys_catalog.cc:565] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:19.933167   751 consensus_queue.cc:237] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [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: "805e27d9c46643919ae53b84396ae193" member_type: VOTER }
I20260812 06:18:19.933588   752 sys_catalog.cc:455] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "805e27d9c46643919ae53b84396ae193" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805e27d9c46643919ae53b84396ae193" member_type: VOTER } }
I20260812 06:18:19.933616   754 sys_catalog.cc:455] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 805e27d9c46643919ae53b84396ae193. Latest consensus state: current_term: 1 leader_uuid: "805e27d9c46643919ae53b84396ae193" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805e27d9c46643919ae53b84396ae193" member_type: VOTER } }
I20260812 06:18:19.933684   752 sys_catalog.cc:458] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.933710   754 sys_catalog.cc:458] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.933929   760 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:19.934806   760 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:19.935002 32752 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:19.936657   760 catalog_manager.cc:1383] Generated new cluster ID: 57c1b9efb39f4441ac53732b760a0717
I20260812 06:18:19.936700   760 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:19.943706   760 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:19.944175   760 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:19.953799   760 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193: Generated new TSK 0
I20260812 06:18:19.953928   760 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:19.967201 32752 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.968909   779 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:19.969010 32752 server_base.cc:1061] running on GCE node
W20260812 06:18:19.968930   781 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:19.969084   784 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:19.969291 32752 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.969336 32752 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:19.969352 32752 hybrid_clock.cc:648] HybridClock initialized: now 1786515499969351 us; error 0 us; skew 500 ppm
I20260812 06:18:19.970090 32752 webserver.cc:533] Webserver started at http://127.31.252.1:45313/ using document root <none> and password file <none>
I20260812 06:18:19.970252 32752 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.970295 32752 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.970363 32752 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.970714 32752 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/instance:
uuid: "8c039e1f161f4a0d885026f2a70b6178"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-bqcl"
I20260812 06:18:19.972115 32752 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:19.973018   792 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:19.973238 32752 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:19.973306 32752 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root
uuid: "8c039e1f161f4a0d885026f2a70b6178"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-bqcl"
I20260812 06:18:19.973369 32752 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-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:19.984892 32752 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.985162 32752 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.985414 32752 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:19.985811 32752 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:19.985847 32752 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.985888 32752 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:19.985915 32752 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.989744 32752 rpc_server.cc:307] RPC server started. Bound to: 127.31.252.1:34005
I20260812 06:18:19.989800   900 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.252.1:34005 every 8 connection(s)
I20260812 06:18:19.997216   901 heartbeater.cc:344] Connected to a master server at 127.31.252.62:39443
I20260812 06:18:19.997336   901 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:19.997560   901 heartbeater.cc:507] Master 127.31.252.62:39443 requested a full tablet report, sending...
I20260812 06:18:19.998188   691 ts_manager.cc:194] Registered new tserver with Master: 8c039e1f161f4a0d885026f2a70b6178 (127.31.252.1:34005)
I20260812 06:18:19.998837   691 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50336
I20260812 06:18:19.998936 32752 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008800289s
I20260812 06:18:20.005663   691 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50348:
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:20.013970   848 tablet_service.cc:1511] Processing CreateTablet for tablet 1485f2a1835840adad8a3881417c9d0d (DEFAULT_TABLE table=heavy-update-compaction-test [id=af9eb6b3c1124fac9d75c6421108f996]), partition=
I20260812 06:18:20.014262   848 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1485f2a1835840adad8a3881417c9d0d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:20.016247   919 tablet_bootstrap.cc:492] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Bootstrap starting.
I20260812 06:18:20.017179   919 tablet_bootstrap.cc:654] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:20.018110   919 tablet_bootstrap.cc:492] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: No bootstrap required, opened a new log
I20260812 06:18:20.018222   919 ts_tablet_manager.cc:1403] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:20.018602   919 raft_consensus.cc:359] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c039e1f161f4a0d885026f2a70b6178" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34005 } }
I20260812 06:18:20.018689   919 raft_consensus.cc:385] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:20.018723   919 raft_consensus.cc:740] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c039e1f161f4a0d885026f2a70b6178, State: Initialized, Role: FOLLOWER
I20260812 06:18:20.018848   919 consensus_queue.cc:260] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [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: "8c039e1f161f4a0d885026f2a70b6178" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34005 } }
I20260812 06:18:20.018918   919 raft_consensus.cc:399] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:20.018953   919 raft_consensus.cc:493] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:20.019001   919 raft_consensus.cc:3060] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:20.020028   919 raft_consensus.cc:515] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c039e1f161f4a0d885026f2a70b6178" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34005 } }
I20260812 06:18:20.020154   919 leader_election.cc:304] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [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: 8c039e1f161f4a0d885026f2a70b6178; no voters: 
I20260812 06:18:20.020342   919 leader_election.cc:290] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:20.020444   921 raft_consensus.cc:2804] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:20.020630   919 ts_tablet_manager.cc:1434] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:20.020646   921 raft_consensus.cc:697] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 1 LEADER]: Becoming Leader. State: Replica: 8c039e1f161f4a0d885026f2a70b6178, State: Running, Role: LEADER
I20260812 06:18:20.020649   901 heartbeater.cc:499] Master 127.31.252.62:39443 was elected leader, sending a full tablet report...
I20260812 06:18:20.020859   921 consensus_queue.cc:237] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [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: "8c039e1f161f4a0d885026f2a70b6178" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34005 } }
I20260812 06:18:20.022082   691 catalog_manager.cc:5719] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8c039e1f161f4a0d885026f2a70b6178 (127.31.252.1). New cstate: current_term: 1 leader_uuid: "8c039e1f161f4a0d885026f2a70b6178" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c039e1f161f4a0d885026f2a70b6178" member_type: VOTER last_known_addr { host: "127.31.252.1" port: 34005 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:20.080231 32752 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:18:20.240578   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushMRSOp(1485f2a1835840adad8a3881417c9d0d): perf score=23.023690
I20260812 06:18:20.394205   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushMRSOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.153s	user 0.110s	sys 0.043s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":32,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":834,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40866,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:20.394804   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling LogGCOp(1485f2a1835840adad8a3881417c9d0d): free 20743880 bytes of WAL
I20260812 06:18:20.395044   801 log_reader.cc:385] T 1485f2a1835840adad8a3881417c9d0d: removed 2 log segments from log reader
I20260812 06:18:20.395102   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000001 (ops 1-6)
I20260812 06:18:20.395135   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000002 (ops 7-11)
I20260812 06:18:20.398878   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: LogGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:20.399272   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d): 20513814 bytes on disk
I20260812 06:18:20.399720   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.400174   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=3.181125
I20260812 06:18:20.420946   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.021s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5021,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:20.421294   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:20.433908   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4967,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.434298   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:20.606212   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.172s	user 0.124s	sys 0.046s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":467,"lbm_read_time_us":13654,"lbm_reads_lt_1ms":569,"lbm_write_time_us":24589,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:18:20.606745   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:20.661721   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.055s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19280,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.662295   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:20.672520   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.673023   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:20.851729   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.179s	user 0.120s	sys 0.055s 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":599,"lbm_read_time_us":13051,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27330,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.852233   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=11.118625
I20260812 06:18:20.886102   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.034s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14215,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:20.886600   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:20.909015   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.022s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.909408   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:20.927075   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.018s	user 0.000s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.927436   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:21.110071   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.182s	user 0.108s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":533,"lbm_read_time_us":11562,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28385,"lbm_writes_lt_1ms":543,"mutex_wait_us":252,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:21.110615   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:21.153236   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.042s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16148,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.153765   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:21.163335   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.163844   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:21.347342   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.183s	user 0.114s	sys 0.058s 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":911,"lbm_read_time_us":10688,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27890,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:21.347810   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:21.400377   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24549,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.400903   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:21.412098   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.412617   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:21.552582   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.140s	user 0.105s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":8094,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25813,"lbm_writes_lt_1ms":543,"mutex_wait_us":250,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:18:21.553319   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=11.118625
I20260812 06:18:21.587544   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.034s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14331,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.588048   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:21.610978   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.023s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.611472   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:21.626231   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.626732   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushMRSOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:21.653054   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushMRSOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1293,"drs_written":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1709,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:21.653702   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling LogGCOp(1485f2a1835840adad8a3881417c9d0d): free 124257236 bytes of WAL
I20260812 06:18:21.653939   801 log_reader.cc:385] T 1485f2a1835840adad8a3881417c9d0d: removed 12 log segments from log reader
I20260812 06:18:21.653987   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000003 (ops 12-16)
I20260812 06:18:21.654016   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000004 (ops 17-21)
I20260812 06:18:21.654032   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000005 (ops 22-26)
I20260812 06:18:21.654062   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000006 (ops 27-30)
I20260812 06:18:21.654096   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000007 (ops 31-35)
I20260812 06:18:21.654146   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000008 (ops 36-40)
I20260812 06:18:21.654179   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000009 (ops 41-45)
I20260812 06:18:21.654203   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000010 (ops 46-50)
I20260812 06:18:21.654234   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000011 (ops 51-55)
I20260812 06:18:21.654263   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000012 (ops 56-60)
I20260812 06:18:21.654294   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000013 (ops 61-65)
I20260812 06:18:21.654330   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000014 (ops 66-70)
I20260812 06:18:21.676621   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: LogGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:21.676983   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d): 472 bytes on disk
I20260812 06:18:21.677433   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d) 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:21.677904   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=3.181125
I20260812 06:18:21.701836   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.024s	user 0.011s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4140,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:21.702351   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:21.715812   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.716252   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:21.933333   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.217s	user 0.149s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020845,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":991,"lbm_read_time_us":15158,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37970,"lbm_writes_lt_1ms":743,"mutex_wait_us":483,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:18:21.933852   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=15.087375
I20260812 06:18:21.984289   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.050s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22089,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:21.984722   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.007869   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.023s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5114,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.008270   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.017817   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.018217   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:22.205828   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.187s	user 0.138s	sys 0.049s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":250,"lbm_read_time_us":14376,"lbm_reads_lt_1ms":673,"lbm_write_time_us":27262,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29184,"update_count":3000}
I20260812 06:18:22.206399   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:22.246899   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16856,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.247362   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.257647   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s 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:22.258044   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:22.424860   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.167s	user 0.118s	sys 0.044s 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":812,"lbm_read_time_us":11844,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27306,"lbm_writes_lt_1ms":543,"mutex_wait_us":242,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:22.425407   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:22.484046   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.058s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20011,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.484522   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.494304   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.494691   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:22.662582   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.168s	user 0.127s	sys 0.036s 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":1143,"lbm_read_time_us":12429,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25778,"lbm_writes_lt_1ms":543,"mutex_wait_us":416,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.663158   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=11.118625
I20260812 06:18:22.703253   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14299,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:22.703835   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.729720   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.026s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.730149   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.740263   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.740722   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:22.903923   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.163s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":585,"lbm_read_time_us":12076,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28031,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:22.904367   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:22.965400   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.061s	user 0.038s	sys 0.018s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21874,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.965947   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:22.980347   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.981474   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushMRSOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:23.020145   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushMRSOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.038s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1401,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1622,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:23.020885   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling LogGCOp(1485f2a1835840adad8a3881417c9d0d): free 121006384 bytes of WAL
I20260812 06:18:23.021112   801 log_reader.cc:385] T 1485f2a1835840adad8a3881417c9d0d: removed 12 log segments from log reader
I20260812 06:18:23.021171   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000015 (ops 71-75)
I20260812 06:18:23.021214   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000016 (ops 76-80)
I20260812 06:18:23.021250   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000017 (ops 81-85)
I20260812 06:18:23.021281   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000018 (ops 86-90)
I20260812 06:18:23.021308   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000019 (ops 91-95)
I20260812 06:18:23.021337   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000020 (ops 96-100)
I20260812 06:18:23.021364   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000021 (ops 101-105)
I20260812 06:18:23.021397   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000022 (ops 106-110)
I20260812 06:18:23.021426   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000023 (ops 111-114)
I20260812 06:18:23.021452   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000024 (ops 115-119)
I20260812 06:18:23.021481   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000025 (ops 120-124)
I20260812 06:18:23.021518   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000026 (ops 125-129)
I20260812 06:18:23.047187   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: LogGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:23.047521   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d): 447 bytes on disk
I20260812 06:18:23.047914   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d) 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:23.048424   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=3.181125
I20260812 06:18:23.063254   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:23.063639   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:23.072316   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3348,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.072680   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:23.285743   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.213s	user 0.115s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2487,"lbm_read_time_us":15995,"lbm_reads_lt_1ms":774,"lbm_write_time_us":30998,"lbm_writes_lt_1ms":743,"mutex_wait_us":1930,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:23.286370   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=18.063937
I20260812 06:18:23.338198   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.052s	user 0.016s	sys 0.036s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":23610,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:23.338665   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:23.350876   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.351425   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:23.524428   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.173s	user 0.106s	sys 0.066s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":12559,"lbm_reads_lt_1ms":664,"lbm_write_time_us":28296,"lbm_writes_lt_1ms":643,"mutex_wait_us":322,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:18:23.525060   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:23.568150   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.043s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19351,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.568642   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:23.588201   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.588627   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:23.744151   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.155s	user 0.106s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":8282,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29471,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:23.744972   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:23.810536   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.065s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24173,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.811043   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:23.826920   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.827497   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:23.983222   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.156s	user 0.107s	sys 0.044s 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":11149,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23957,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:18:23.983805   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:24.038951   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.055s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16827,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.039423   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:24.049124   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.049485   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:24.206969   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.157s	user 0.097s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":88,"lbm_read_time_us":11522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25562,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:18:24.207554   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=10.126437
I20260812 06:18:24.236690   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.029s	user 0.006s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12312,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.237160   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:24.251037   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.251617   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:24.412034   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.160s	user 0.078s	sys 0.067s 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":750,"lbm_read_time_us":9421,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24243,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:18:24.412576   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=14.095187
I20260812 06:18:24.458865   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.046s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19350,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.459391   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:24.468535   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.469172   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushMRSOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:24.499085   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushMRSOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1201,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1891,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:24.499828   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling LogGCOp(1485f2a1835840adad8a3881417c9d0d): free 133024646 bytes of WAL
I20260812 06:18:24.500100   801 log_reader.cc:385] T 1485f2a1835840adad8a3881417c9d0d: removed 13 log segments from log reader
I20260812 06:18:24.500161   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000027 (ops 130-134)
I20260812 06:18:24.500195   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000028 (ops 135-139)
I20260812 06:18:24.500221   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000029 (ops 140-144)
I20260812 06:18:24.500258   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000030 (ops 145-148)
I20260812 06:18:24.500298   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000031 (ops 149-153)
I20260812 06:18:24.500336   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000032 (ops 154-158)
I20260812 06:18:24.500373   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000033 (ops 159-163)
I20260812 06:18:24.500411   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000034 (ops 164-168)
I20260812 06:18:24.500447   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000035 (ops 169-173)
I20260812 06:18:24.500494   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000036 (ops 174-178)
I20260812 06:18:24.500533   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000037 (ops 179-183)
I20260812 06:18:24.500571   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000038 (ops 184-188)
I20260812 06:18:24.500608   801 log.cc:1079] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: Deleting log segment in path: /tmp/dist-test-taskjYnC51/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494636983-32752-0/minicluster-data/ts-0-root/wals/1485f2a1835840adad8a3881417c9d0d/wal-000000039 (ops 189-193)
I20260812 06:18:24.524493   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: LogGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:24.525084   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d): 492 bytes on disk
I20260812 06:18:24.525554   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: UndoDeltaBlockGCOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.526194   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=3.181125
I20260812 06:18:24.547511   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.021s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4553930,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:18:24.547958   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=2.188937
I20260812 06:18:24.563076   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":5969,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:24.563509   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d): perf score=1.000000
I20260812 06:18:24.702566 32752 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.622s	user 1.687s	sys 0.186s
I20260812 06:18:24.760639   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: MajorDeltaCompactionOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.197s	user 0.148s	sys 0.047s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14280,"lbm_reads_lt_1ms":770,"lbm_write_time_us":31895,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3500}
I20260812 06:18:24.761106   902 maintenance_manager.cc:419] P 8c039e1f161f4a0d885026f2a70b6178: Scheduling FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d): perf score=10.126437
I20260812 06:18:24.778367 32752 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.002s	sys 0.000s
I20260812 06:18:24.778816 32752 tablet_server.cc:179] TabletServer@127.31.252.1:0 shutting down...
I20260812 06:18:24.789971   801 maintenance_manager.cc:643] P 8c039e1f161f4a0d885026f2a70b6178: FlushDeltaMemStoresOp(1485f2a1835840adad8a3881417c9d0d) complete. Timing: real 0.029s	user 0.022s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11835,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.790479 32752 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:24.790680 32752 tablet_replica.cc:333] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178: stopping tablet replica
I20260812 06:18:24.790805 32752 raft_consensus.cc:2243] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.790962 32752 raft_consensus.cc:2272] T 1485f2a1835840adad8a3881417c9d0d P 8c039e1f161f4a0d885026f2a70b6178 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.793764 32752 tablet_server.cc:196] TabletServer@127.31.252.1:0 shutdown complete.
I20260812 06:18:24.822402 32752 master.cc:562] Master@127.31.252.62:39443 shutting down...
I20260812 06:18:24.825001 32752 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.825133 32752 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.825201 32752 tablet_replica.cc:333] T 00000000000000000000000000000000 P 805e27d9c46643919ae53b84396ae193: stopping tablet replica
I20260812 06:18:24.837023 32752 master.cc:584] Master@127.31.252.62:39443 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5017 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10258 ms total)

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