[==========] 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:27.301146 25895 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.73.254:44705
I20260812 06:18:27.302174 25895 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:27.302814 25895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.309077 25901 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:27.309096 25903 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:27.309141 25895 server_base.cc:1061] running on GCE node
W20260812 06:18:27.309399 25906 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:27.309919 25895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.310036 25895 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:27.310084 25895 hybrid_clock.cc:648] HybridClock initialized: now 1786515507310082 us; error 0 us; skew 500 ppm
I20260812 06:18:27.311803 25895 webserver.cc:533] Webserver started at http://127.25.73.254:39669/ using document root <none> and password file <none>
I20260812 06:18:27.312348 25895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.312428 25895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.312675 25895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.314361 25895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/master-0-root/instance:
uuid: "c3f90e8b6da44300ab48b6c7756c31cb"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-zr1t"
I20260812 06:18:27.317744 25895 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.319819 25919 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:27.320798 25895 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:27.320922 25895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/master-0-root
uuid: "c3f90e8b6da44300ab48b6c7756c31cb"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-zr1t"
I20260812 06:18:27.321019 25895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-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:27.344429 25895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.345135 25895 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:27.345331 25895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.353060 25895 rpc_server.cc:307] RPC server started. Bound to: 127.25.73.254:44705
I20260812 06:18:27.353068 25995 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.73.254:44705 every 8 connection(s)
I20260812 06:18:27.355249 25996 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:27.360441 25996 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: Bootstrap starting.
I20260812 06:18:27.362752 25996 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.363626 25996 log.cc:826] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.365227 25996 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: No bootstrap required, opened a new log
I20260812 06:18:27.367897 25996 raft_consensus.cc:359] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER }
I20260812 06:18:27.368057 25996 raft_consensus.cc:385] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.368098 25996 raft_consensus.cc:740] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3f90e8b6da44300ab48b6c7756c31cb, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.368701 25996 consensus_queue.cc:260] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [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: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER }
I20260812 06:18:27.368870 25996 raft_consensus.cc:399] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.368943 25996 raft_consensus.cc:493] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.369117 25996 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.369886 25996 raft_consensus.cc:515] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER }
I20260812 06:18:27.370318 25996 leader_election.cc:304] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [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: c3f90e8b6da44300ab48b6c7756c31cb; no voters: 
I20260812 06:18:27.370635 25996 leader_election.cc:290] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.370779 26002 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.371037 26002 raft_consensus.cc:697] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 1 LEADER]: Becoming Leader. State: Replica: c3f90e8b6da44300ab48b6c7756c31cb, State: Running, Role: LEADER
I20260812 06:18:27.371445 26002 consensus_queue.cc:237] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [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: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER }
I20260812 06:18:27.371661 25996 sys_catalog.cc:565] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.373299 26005 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [sys.catalog]: SysCatalogTable state changed. Reason: New leader c3f90e8b6da44300ab48b6c7756c31cb. Latest consensus state: current_term: 1 leader_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER } }
I20260812 06:18:27.373363 26004 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3f90e8b6da44300ab48b6c7756c31cb" member_type: VOTER } }
I20260812 06:18:27.373433 26005 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.373453 26004 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.374056 25895 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:27.375847 26025 catalog_manager.cc:1594] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:27.375911 26025 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:27.375990 26022 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.376724 26022 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.381291 26022 catalog_manager.cc:1383] Generated new cluster ID: 9054f1ab015949fa9be8fd1e25d14dbb
I20260812 06:18:27.381356 26022 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.394551 26022 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.395354 26022 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.409425 26022 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: Generated new TSK 0
I20260812 06:18:27.410051 26022 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.438967 25895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.442068 26036 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:27.442108 26034 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:27.442122 26038 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:27.442581 25895 server_base.cc:1061] running on GCE node
I20260812 06:18:27.442780 25895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.442826 25895 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:27.442843 25895 hybrid_clock.cc:648] HybridClock initialized: now 1786515507442843 us; error 0 us; skew 500 ppm
I20260812 06:18:27.443846 25895 webserver.cc:533] Webserver started at http://127.25.73.193:34989/ using document root <none> and password file <none>
I20260812 06:18:27.444031 25895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.444092 25895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.444192 25895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.444603 25895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/instance:
uuid: "f69f39fbb4fa4f9b9c629cc194932a8e"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-zr1t"
I20260812 06:18:27.446211 25895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:27.447230 26044 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:27.447479 25895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:27.447551 25895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root
uuid: "f69f39fbb4fa4f9b9c629cc194932a8e"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-zr1t"
I20260812 06:18:27.447651 25895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-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:27.452533 25895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.452926 25895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.453416 25895 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.454272 25895 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.454324 25895 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.454389 25895 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.454430 25895 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.461221 25895 rpc_server.cc:307] RPC server started. Bound to: 127.25.73.193:40663
I20260812 06:18:27.461417 26147 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.73.193:40663 every 8 connection(s)
I20260812 06:18:27.471022 26148 heartbeater.cc:344] Connected to a master server at 127.25.73.254:44705
I20260812 06:18:27.471249 26148 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.471654 26148 heartbeater.cc:507] Master 127.25.73.254:44705 requested a full tablet report, sending...
I20260812 06:18:27.473102 25942 ts_manager.cc:194] Registered new tserver with Master: f69f39fbb4fa4f9b9c629cc194932a8e (127.25.73.193:40663)
I20260812 06:18:27.473238 25895 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011298367s
I20260812 06:18:27.474403 25942 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45716
I20260812 06:18:27.482420 25942 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45724:
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:27.495268 26092 tablet_service.cc:1511] Processing CreateTablet for tablet 1ec38b898f354e4896d6dedcc5a9bafa (DEFAULT_TABLE table=heavy-update-compaction-test [id=b24c84243a024947b8f9253f74838d4f]), partition=
I20260812 06:18:27.495685 26092 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1ec38b898f354e4896d6dedcc5a9bafa. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.498157 26168 tablet_bootstrap.cc:492] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Bootstrap starting.
I20260812 06:18:27.499260 26168 tablet_bootstrap.cc:654] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.500613 26168 tablet_bootstrap.cc:492] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: No bootstrap required, opened a new log
I20260812 06:18:27.500725 26168 ts_tablet_manager.cc:1403] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.501219 26168 raft_consensus.cc:359] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f69f39fbb4fa4f9b9c629cc194932a8e" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 40663 } }
I20260812 06:18:27.501353 26168 raft_consensus.cc:385] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.501405 26168 raft_consensus.cc:740] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f69f39fbb4fa4f9b9c629cc194932a8e, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.501648 26168 consensus_queue.cc:260] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [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: "f69f39fbb4fa4f9b9c629cc194932a8e" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 40663 } }
I20260812 06:18:27.501751 26168 raft_consensus.cc:399] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.501788 26168 raft_consensus.cc:493] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.501839 26168 raft_consensus.cc:3060] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.502797 26168 raft_consensus.cc:515] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f69f39fbb4fa4f9b9c629cc194932a8e" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 40663 } }
I20260812 06:18:27.502945 26168 leader_election.cc:304] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [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: f69f39fbb4fa4f9b9c629cc194932a8e; no voters: 
I20260812 06:18:27.503147 26168 leader_election.cc:290] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.503393 26175 raft_consensus.cc:2804] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.503587 26168 ts_tablet_manager.cc:1434] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:27.503798 26175 raft_consensus.cc:697] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 1 LEADER]: Becoming Leader. State: Replica: f69f39fbb4fa4f9b9c629cc194932a8e, State: Running, Role: LEADER
I20260812 06:18:27.503961 26148 heartbeater.cc:499] Master 127.25.73.254:44705 was elected leader, sending a full tablet report...
I20260812 06:18:27.504002 26175 consensus_queue.cc:237] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [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: "f69f39fbb4fa4f9b9c629cc194932a8e" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 40663 } }
I20260812 06:18:27.506834 25942 catalog_manager.cc:5719] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e reported cstate change: term changed from 0 to 1, leader changed from <none> to f69f39fbb4fa4f9b9c629cc194932a8e (127.25.73.193). New cstate: current_term: 1 leader_uuid: "f69f39fbb4fa4f9b9c629cc194932a8e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f69f39fbb4fa4f9b9c629cc194932a8e" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 40663 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.572119 25895 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.011s
I20260812 06:18:27.712409 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=19.054940
I20260812 06:18:27.880726 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.168s	user 0.121s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":215,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":769,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41088,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":157,"threads_started":1,"update_count":1500}
I20260812 06:18:27.881916 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa): free 20743831 bytes of WAL
I20260812 06:18:27.882220 26049 log_reader.cc:385] T 1ec38b898f354e4896d6dedcc5a9bafa: removed 2 log segments from log reader
I20260812 06:18:27.882310 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000001 (ops 1-6)
I20260812 06:18:27.882421 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000002 (ops 7-11)
I20260812 06:18:27.887981 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:27.888343 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:27.906599 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.018s	user 0.012s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.907310 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.048764 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.141s	user 0.104s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":9146,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22255,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":299,"threads_started":5,"update_count":2000}
I20260812 06:18:28.049443 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa): 16411395 bytes on disk
I20260812 06:18:28.050019 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.050544 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:28.084901 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15085,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.085353 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:28.095999 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.096513 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.219250 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.123s	user 0.090s	sys 0.032s 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":713,"lbm_read_time_us":8461,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25478,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:28.219862 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:28.259789 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.040s	user 0.029s	sys 0.009s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":18250,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.260247 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:28.275173 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.275740 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.405496 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.130s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":835,"lbm_read_time_us":9848,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25076,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:28.407140 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:28.455643 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.048s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.456169 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:28.466746 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.467181 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.606376 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.139s	user 0.123s	sys 0.016s 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":198,"lbm_read_time_us":11229,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21971,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2000}
I20260812 06:18:28.606896 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:28.653810 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.047s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21984,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.654315 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:28.664952 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.665638 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.796446 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.131s	user 0.106s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":788,"lbm_read_time_us":9455,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24894,"lbm_writes_lt_1ms":443,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:28.797169 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:28.842172 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20068,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.842643 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:28.852914 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.853540 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:28.979318 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.126s	user 0.108s	sys 0.017s 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":343,"lbm_read_time_us":8864,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23510,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:28.979863 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=10.126437
I20260812 06:18:29.019589 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.040s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14784,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.020081 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:29.031500 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.032150 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:29.063802 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.031s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1138,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1789,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:29.064576 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa): free 112239359 bytes of WAL
I20260812 06:18:29.064800 26049 log_reader.cc:385] T 1ec38b898f354e4896d6dedcc5a9bafa: removed 11 log segments from log reader
I20260812 06:18:29.064859 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000003 (ops 12-16)
I20260812 06:18:29.064913 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000004 (ops 17-21)
I20260812 06:18:29.064970 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000005 (ops 22-26)
I20260812 06:18:29.065007 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000006 (ops 27-31)
I20260812 06:18:29.065042 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000007 (ops 32-36)
I20260812 06:18:29.065076 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000008 (ops 37-41)
I20260812 06:18:29.065114 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000009 (ops 42-46)
I20260812 06:18:29.065150 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000010 (ops 47-51)
I20260812 06:18:29.065187 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000011 (ops 52-56)
I20260812 06:18:29.065223 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000012 (ops 57-60)
I20260812 06:18:29.065260 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000013 (ops 61-65)
I20260812 06:18:29.090577 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:29.090960 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa): 447 bytes on disk
I20260812 06:18:29.091362 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa) 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:29.091845 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=3.181125
I20260812 06:18:29.105211 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5087239,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:18:29.105664 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.196750
I20260812 06:18:29.115562 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3235,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:29.116118 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:29.287798 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.172s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":521,"lbm_read_time_us":13056,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33041,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:29.288250 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:29.345265 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.057s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25593,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.345891 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:29.366057 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.020s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.366508 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:29.518134 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.151s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":8861,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29379,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:18:29.518833 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:29.574090 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:29.574592 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:29.730052 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.155s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1091,"lbm_read_time_us":10175,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26426,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.730701 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:29.783792 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.053s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22874,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.784283 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:29.796855 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.797354 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:29.990665 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.193s	user 0.153s	sys 0.036s 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":346,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31679,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:29.991372 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:30.036815 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20222,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.037369 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.054976 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.055430 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:30.213953 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.158s	user 0.117s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":897,"lbm_read_time_us":9338,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30679,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:18:30.214458 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:30.267251 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.053s	user 0.036s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.267753 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.279302 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.279994 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:30.431154 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.151s	user 0.123s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1351,"lbm_read_time_us":11483,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29958,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:30.431936 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=11.118625
I20260812 06:18:30.472390 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.040s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15239,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.473225 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.485006 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.485420 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.494434 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3405,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.494836 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:30.526597 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":135,"dirs.run_wall_time_us":1146,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1680,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:30.527359 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa): free 128867403 bytes of WAL
I20260812 06:18:30.527621 26049 log_reader.cc:385] T 1ec38b898f354e4896d6dedcc5a9bafa: removed 13 log segments from log reader
I20260812 06:18:30.527683 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000014 (ops 66-70)
I20260812 06:18:30.527719 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000015 (ops 71-75)
I20260812 06:18:30.527750 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000016 (ops 76-80)
I20260812 06:18:30.527776 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000017 (ops 81-85)
I20260812 06:18:30.527810 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000018 (ops 86-90)
I20260812 06:18:30.527835 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000019 (ops 91-94)
I20260812 06:18:30.527864 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000020 (ops 95-99)
I20260812 06:18:30.527892 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000021 (ops 100-104)
I20260812 06:18:30.527920 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000022 (ops 105-108)
I20260812 06:18:30.527949 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000023 (ops 109-113)
I20260812 06:18:30.527997 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000024 (ops 114-118)
I20260812 06:18:30.528020 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000025 (ops 119-122)
I20260812 06:18:30.528043 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000026 (ops 123-127)
I20260812 06:18:30.561116 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.034s	user 0.001s	sys 0.028s Metrics: {}
I20260812 06:18:30.561684 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.582585 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.021s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.583071 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.593122 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.593619 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa): 483 bytes on disk
I20260812 06:18:30.594017 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.594936 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:30.834797 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.240s	user 0.160s	sys 0.069s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":291,"lbm_read_time_us":15713,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40701,"lbm_writes_lt_1ms":743,"mutex_wait_us":34,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:30.835595 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=18.063937
I20260812 06:18:30.900990 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.065s	user 0.024s	sys 0.037s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24142,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:30.901676 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:30.912879 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.913502 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:31.109834 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.196s	user 0.126s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":14242,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34928,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":3000}
I20260812 06:18:31.110472 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:31.166162 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.056s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24039,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.166695 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:31.184454 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.184991 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:31.352907 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.168s	user 0.119s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1158,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29207,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:31.353574 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:31.417497 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.064s	user 0.019s	sys 0.040s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":22371,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.418125 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:31.437965 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.020s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.438584 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:31.654147 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.215s	user 0.141s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1906,"lbm_read_time_us":12586,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32651,"lbm_writes_lt_1ms":543,"mutex_wait_us":742,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.654947 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:31.727994 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.073s	user 0.039s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":33262,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.728611 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:31.748085 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":500}
I20260812 06:18:31.749596 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:31.960196 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.210s	user 0.160s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":987,"lbm_read_time_us":15976,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33477,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:31.961158 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=14.095187
I20260812 06:18:32.009786 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.048s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20227,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.010327 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:32.026649 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.027426 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:32.057500 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushMRSOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.030s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1211,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:32.058710 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa): 447 bytes on disk
I20260812 06:18:32.059449 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: UndoDeltaBlockGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":128,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.060187 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:32.075739 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.076215 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa): free 112239600 bytes of WAL
I20260812 06:18:32.076454 26049 log_reader.cc:385] T 1ec38b898f354e4896d6dedcc5a9bafa: removed 11 log segments from log reader
I20260812 06:18:32.076498 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000027 (ops 128-132)
I20260812 06:18:32.076529 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000028 (ops 133-137)
I20260812 06:18:32.076573 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000029 (ops 138-142)
I20260812 06:18:32.076617 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000030 (ops 143-147)
I20260812 06:18:32.076683 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000031 (ops 148-152)
I20260812 06:18:32.076745 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000032 (ops 153-157)
I20260812 06:18:32.076783 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000033 (ops 158-162)
I20260812 06:18:32.076820 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000034 (ops 163-166)
I20260812 06:18:32.076859 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000035 (ops 167-171)
I20260812 06:18:32.076896 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000036 (ops 172-176)
I20260812 06:18:32.076934 26049 log.cc:1079] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/1ec38b898f354e4896d6dedcc5a9bafa/wal-000000037 (ops 177-181)
I20260812 06:18:32.103637 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: LogGCOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:32.104176 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:32.112274 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.008s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1395006,"delete_count":0,"lbm_write_time_us":1358,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:18:32.112762 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.196750
I20260812 06:18:32.123509 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:32.124034 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:32.349797 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.226s	user 0.158s	sys 0.059s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979778,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":835,"lbm_read_time_us":16819,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35719,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23808,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:18:32.350524 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=18.063937
I20260812 06:18:32.425227 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.075s	user 0.042s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28655,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.425818 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=2.188937
I20260812 06:18:32.436333 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: FlushDeltaMemStoresOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.436856 26149 maintenance_manager.cc:419] P f69f39fbb4fa4f9b9c629cc194932a8e: Scheduling MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa): perf score=1.000000
I20260812 06:18:32.467128 25895 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.895s	user 1.867s	sys 0.133s
I20260812 06:18:32.543242 25895 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.002s	sys 0.000s
I20260812 06:18:32.543900 25895 tablet_server.cc:179] TabletServer@127.25.73.193:0 shutting down...
I20260812 06:18:32.607678 26049 maintenance_manager.cc:643] P f69f39fbb4fa4f9b9c629cc194932a8e: MajorDeltaCompactionOp(1ec38b898f354e4896d6dedcc5a9bafa) complete. Timing: real 0.171s	user 0.116s	sys 0.054s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":14351,"lbm_reads_lt_1ms":668,"lbm_write_time_us":30644,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":105600,"update_count":3000}
I20260812 06:18:32.608479 25895 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:32.608903 25895 tablet_replica.cc:333] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e: stopping tablet replica
I20260812 06:18:32.609160 25895 raft_consensus.cc:2243] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.609400 25895 raft_consensus.cc:2272] T 1ec38b898f354e4896d6dedcc5a9bafa P f69f39fbb4fa4f9b9c629cc194932a8e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.626843 25895 tablet_server.cc:196] TabletServer@127.25.73.193:0 shutdown complete.
I20260812 06:18:32.661211 25895 master.cc:562] Master@127.25.73.254:44705 shutting down...
I20260812 06:18:32.665208 25895 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.665414 25895 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.665545 25895 tablet_replica.cc:333] T 00000000000000000000000000000000 P c3f90e8b6da44300ab48b6c7756c31cb: stopping tablet replica
I20260812 06:18:32.678103 25895 master.cc:584] Master@127.25.73.254:44705 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5473 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:32.785511 25895 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.73.254:40801
I20260812 06:18:32.786123 25895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.788209 26206 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:32.788218 26205 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:32.788264 25895 server_base.cc:1061] running on GCE node
W20260812 06:18:32.788244 26209 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:32.788641 25895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.788691 25895 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:32.788708 25895 hybrid_clock.cc:648] HybridClock initialized: now 1786515512788708 us; error 0 us; skew 500 ppm
I20260812 06:18:32.789717 25895 webserver.cc:533] Webserver started at http://127.25.73.254:33809/ using document root <none> and password file <none>
I20260812 06:18:32.789911 25895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.789990 25895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.790086 25895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.790524 25895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/master-0-root/instance:
uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-zr1t"
I20260812 06:18:32.792105 25895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:32.793067 26218 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:32.793335 25895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:32.793445 25895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/master-0-root
uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-zr1t"
I20260812 06:18:32.793563 25895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-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:32.802397 25895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.802759 25895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.807508 25895 rpc_server.cc:307] RPC server started. Bound to: 127.25.73.254:40801
I20260812 06:18:32.815618 26303 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.73.254:40801 every 8 connection(s)
I20260812 06:18:32.816102 26306 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:32.818356 26306 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d: Bootstrap starting.
I20260812 06:18:32.819180 26306 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.820238 26306 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d: No bootstrap required, opened a new log
I20260812 06:18:32.820680 26306 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER }
I20260812 06:18:32.820768 26306 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.820818 26306 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0dd7af38b5744c62bfb9f8c0d8acf04d, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.821028 26306 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [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: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER }
I20260812 06:18:32.821113 26306 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.821182 26306 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.821265 26306 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.822081 26306 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER }
I20260812 06:18:32.822238 26306 leader_election.cc:304] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [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: 0dd7af38b5744c62bfb9f8c0d8acf04d; no voters: 
I20260812 06:18:32.822510 26306 leader_election.cc:290] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.822646 26311 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.822906 26311 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 1 LEADER]: Becoming Leader. State: Replica: 0dd7af38b5744c62bfb9f8c0d8acf04d, State: Running, Role: LEADER
I20260812 06:18:32.823067 26306 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:32.823048 26311 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [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: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER }
I20260812 06:18:32.823527 26312 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER } }
I20260812 06:18:32.823634 26312 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.823544 26314 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0dd7af38b5744c62bfb9f8c0d8acf04d. Latest consensus state: current_term: 1 leader_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0dd7af38b5744c62bfb9f8c0d8acf04d" member_type: VOTER } }
I20260812 06:18:32.823948 26314 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.823966 26316 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:32.824872 26316 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:32.825320 25895 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:32.826690 26316 catalog_manager.cc:1383] Generated new cluster ID: fce72f5162d3445287a4551c76d3f3ca
I20260812 06:18:32.826749 26316 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:32.840602 26316 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:32.841264 26316 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:32.852192 26316 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d: Generated new TSK 0
I20260812 06:18:32.852423 26316 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:32.857657 25895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.859637 26340 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:32.859731 26342 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:32.859767 25895 server_base.cc:1061] running on GCE node
W20260812 06:18:32.859875 26344 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:32.860086 25895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.860131 25895 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:32.860147 25895 hybrid_clock.cc:648] HybridClock initialized: now 1786515512860148 us; error 0 us; skew 500 ppm
I20260812 06:18:32.860913 25895 webserver.cc:533] Webserver started at http://127.25.73.193:36529/ using document root <none> and password file <none>
I20260812 06:18:32.861057 25895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.861104 25895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.861159 25895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.861568 25895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/instance:
uuid: "62ae26746c7a4e4782d86ab72c3a0794"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-zr1t"
I20260812 06:18:32.863168 25895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:32.864043 26351 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:32.864279 25895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:32.864372 25895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root
uuid: "62ae26746c7a4e4782d86ab72c3a0794"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-zr1t"
I20260812 06:18:32.864454 25895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-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:32.890202 25895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.890668 25895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.891019 25895 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:32.891518 25895 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:32.891583 25895 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.891644 25895 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:32.891695 25895 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.896034 25895 rpc_server.cc:307] RPC server started. Bound to: 127.25.73.193:33207
I20260812 06:18:32.896103 26445 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.73.193:33207 every 8 connection(s)
I20260812 06:18:32.905880 26446 heartbeater.cc:344] Connected to a master server at 127.25.73.254:40801
I20260812 06:18:32.906004 26446 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:32.906221 26446 heartbeater.cc:507] Master 127.25.73.254:40801 requested a full tablet report, sending...
I20260812 06:18:32.906917 26245 ts_manager.cc:194] Registered new tserver with Master: 62ae26746c7a4e4782d86ab72c3a0794 (127.25.73.193:33207)
I20260812 06:18:32.907536 25895 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011015354s
I20260812 06:18:32.907744 26245 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43886
I20260812 06:18:32.914779 26245 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43902:
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:32.924484 26395 tablet_service.cc:1511] Processing CreateTablet for tablet f21d7f9403a14bf7918ba85017bebfff (DEFAULT_TABLE table=heavy-update-compaction-test [id=b0afb6a5385d4aa39b5e0bae65ae6c4d]), partition=
I20260812 06:18:32.924786 26395 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f21d7f9403a14bf7918ba85017bebfff. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.926949 26468 tablet_bootstrap.cc:492] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Bootstrap starting.
I20260812 06:18:32.927902 26468 tablet_bootstrap.cc:654] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.928992 26468 tablet_bootstrap.cc:492] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: No bootstrap required, opened a new log
I20260812 06:18:32.929105 26468 ts_tablet_manager.cc:1403] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:32.929586 26468 raft_consensus.cc:359] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62ae26746c7a4e4782d86ab72c3a0794" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 33207 } }
I20260812 06:18:32.929682 26468 raft_consensus.cc:385] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.929705 26468 raft_consensus.cc:740] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 62ae26746c7a4e4782d86ab72c3a0794, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.929868 26468 consensus_queue.cc:260] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [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: "62ae26746c7a4e4782d86ab72c3a0794" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 33207 } }
I20260812 06:18:32.929988 26468 raft_consensus.cc:399] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.930055 26468 raft_consensus.cc:493] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.930114 26468 raft_consensus.cc:3060] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.930949 26468 raft_consensus.cc:515] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62ae26746c7a4e4782d86ab72c3a0794" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 33207 } }
I20260812 06:18:32.931077 26468 leader_election.cc:304] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [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: 62ae26746c7a4e4782d86ab72c3a0794; no voters: 
I20260812 06:18:32.931218 26468 leader_election.cc:290] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.931361 26470 raft_consensus.cc:2804] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.931535 26470 raft_consensus.cc:697] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 1 LEADER]: Becoming Leader. State: Replica: 62ae26746c7a4e4782d86ab72c3a0794, State: Running, Role: LEADER
I20260812 06:18:32.931559 26446 heartbeater.cc:499] Master 127.25.73.254:40801 was elected leader, sending a full tablet report...
I20260812 06:18:32.931687 26470 consensus_queue.cc:237] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [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: "62ae26746c7a4e4782d86ab72c3a0794" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 33207 } }
I20260812 06:18:32.931874 26468 ts_tablet_manager.cc:1434] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:32.932969 26245 catalog_manager.cc:5719] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 reported cstate change: term changed from 0 to 1, leader changed from <none> to 62ae26746c7a4e4782d86ab72c3a0794 (127.25.73.193). New cstate: current_term: 1 leader_uuid: "62ae26746c7a4e4782d86ab72c3a0794" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62ae26746c7a4e4782d86ab72c3a0794" member_type: VOTER last_known_addr { host: "127.25.73.193" port: 33207 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:32.993690 25895 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.010s
I20260812 06:18:33.146952 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff): perf score=19.054940
I20260812 06:18:33.294597 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.147s	user 0.103s	sys 0.044s Metrics: {"bytes_written":12717736,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":779,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35556,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":768,"update_count":1550}
I20260812 06:18:33.295392 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling LogGCOp(f21d7f9403a14bf7918ba85017bebfff): free 20743880 bytes of WAL
I20260812 06:18:33.295720 26358 log_reader.cc:385] T f21d7f9403a14bf7918ba85017bebfff: removed 2 log segments from log reader
I20260812 06:18:33.295809 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000001 (ops 1-6)
I20260812 06:18:33.295866 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000002 (ops 7-11)
I20260812 06:18:33.301162 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: LogGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:33.302006 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff): 16411394 bytes on disk
I20260812 06:18:33.302400 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff) 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:33.302788 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:33.318097 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3824,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:33.318516 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:33.329293 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4174,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:33.329773 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:33.499577 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.170s	user 0.113s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774804,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1494,"lbm_read_time_us":12153,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27522,"lbm_writes_lt_1ms":543,"mutex_wait_us":194,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":368,"threads_started":5,"update_count":2500}
I20260812 06:18:33.500173 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:33.557251 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.057s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.557715 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:33.568632 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.569284 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:33.746999 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.178s	user 0.112s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":705,"lbm_read_time_us":12949,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29468,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:18:33.747439 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:33.808266 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.061s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21633,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:33.808760 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:33.819764 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.820209 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:33.998297 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.178s	user 0.105s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":686,"lbm_read_time_us":12873,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30401,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:33.999038 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:34.054580 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.055s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20186,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.055096 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:34.065940 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.066383 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:34.258773 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.192s	user 0.125s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":13537,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32145,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:18:34.259374 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:34.312244 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.053s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.312745 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:34.334728 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.335359 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:34.507405 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.172s	user 0.103s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":11295,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29364,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:34.508158 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:34.558084 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21948,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.558607 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:34.570501 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.570997 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:34.611183 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.040s	user 0.030s	sys 0.006s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1397,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2585,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:34.611917 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling LogGCOp(f21d7f9403a14bf7918ba85017bebfff): free 124257243 bytes of WAL
I20260812 06:18:34.612190 26358 log_reader.cc:385] T f21d7f9403a14bf7918ba85017bebfff: removed 12 log segments from log reader
I20260812 06:18:34.612254 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000003 (ops 12-16)
I20260812 06:18:34.612293 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000004 (ops 17-21)
I20260812 06:18:34.612323 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000005 (ops 22-26)
I20260812 06:18:34.612356 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000006 (ops 27-31)
I20260812 06:18:34.612380 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000007 (ops 32-36)
I20260812 06:18:34.612406 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000008 (ops 37-41)
I20260812 06:18:34.612435 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000009 (ops 42-46)
I20260812 06:18:34.612475 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000010 (ops 47-51)
I20260812 06:18:34.612504 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000011 (ops 52-56)
I20260812 06:18:34.612542 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000012 (ops 57-61)
I20260812 06:18:34.612581 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000013 (ops 62-66)
I20260812 06:18:34.612622 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000014 (ops 67-70)
I20260812 06:18:34.645279 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: LogGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:34.645716 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=3.181125
I20260812 06:18:34.662921 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.017s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.663381 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff): 472 bytes on disk
I20260812 06:18:34.663771 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.664204 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:34.673954 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3747,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.674309 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:34.917623 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.243s	user 0.154s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":782,"lbm_read_time_us":16208,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42099,"lbm_writes_lt_1ms":743,"mutex_wait_us":69,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18816,"thread_start_us":123,"threads_started":1,"update_count":3500}
I20260812 06:18:34.918342 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=18.063937
I20260812 06:18:34.975392 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.056s	user 0.035s	sys 0.019s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25506,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:34.975876 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:35.142617 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774570,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1035,"lbm_read_time_us":11810,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29489,"lbm_writes_lt_1ms":543,"mutex_wait_us":440,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:35.143298 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:35.210918 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.067s	user 0.027s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.211416 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:35.222345 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.222815 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:35.411259 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.188s	user 0.140s	sys 0.046s 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":359,"lbm_read_time_us":14716,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30928,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:35.411896 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=11.118625
I20260812 06:18:35.441226 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.029s	user 0.022s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12998,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:35.441799 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:35.462185 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.020s	user 0.007s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7516,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.462746 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:35.632284 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.169s	user 0.112s	sys 0.044s 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":808,"lbm_read_time_us":10948,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23332,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:18:35.632992 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:35.695587 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.062s	user 0.029s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27081,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.696098 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:35.707917 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.708385 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:35.866837 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.158s	user 0.113s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":10291,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31633,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:35.867372 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:35.917884 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.050s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18411,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.918476 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:35.934332 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.935040 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:36.106211 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.171s	user 0.129s	sys 0.036s 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":210,"lbm_read_time_us":10731,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34005,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:18:36.107179 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=12.110812
I20260812 06:18:36.151708 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.044s	user 0.019s	sys 0.020s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":16999,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:18:36.152212 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.170157 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.018s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3306,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:36.170603 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.179812 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3485,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.180212 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:36.213405 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1311,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1752,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:36.214160 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling LogGCOp(f21d7f9403a14bf7918ba85017bebfff): free 124710306 bytes of WAL
I20260812 06:18:36.214422 26358 log_reader.cc:385] T f21d7f9403a14bf7918ba85017bebfff: removed 12 log segments from log reader
I20260812 06:18:36.214483 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000015 (ops 71-75)
I20260812 06:18:36.214522 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000016 (ops 76-80)
I20260812 06:18:36.214555 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000017 (ops 81-85)
I20260812 06:18:36.214582 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000018 (ops 86-90)
I20260812 06:18:36.214617 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000019 (ops 91-95)
I20260812 06:18:36.214639 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000020 (ops 96-100)
I20260812 06:18:36.214661 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000021 (ops 101-105)
I20260812 06:18:36.214690 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000022 (ops 106-110)
I20260812 06:18:36.214717 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000023 (ops 111-115)
I20260812 06:18:36.214749 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000024 (ops 116-120)
I20260812 06:18:36.214782 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000025 (ops 121-125)
I20260812 06:18:36.214811 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000026 (ops 126-130)
I20260812 06:18:36.245199 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: LogGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.031s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:18:36.245772 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff): 482 bytes on disk
I20260812 06:18:36.246384 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.247088 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.269227 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.269790 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.280086 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.280562 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:36.527544 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.247s	user 0.166s	sys 0.066s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979832,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":203,"lbm_read_time_us":16841,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40443,"lbm_writes_lt_1ms":743,"mutex_wait_us":58,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:36.528291 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=18.063937
I20260812 06:18:36.585480 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25605,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.586058 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.602845 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.017s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.603367 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:36.777691 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.174s	user 0.138s	sys 0.035s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1461,"lbm_read_time_us":13724,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35506,"lbm_writes_lt_1ms":643,"mutex_wait_us":663,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:18:36.778452 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:36.823051 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.044s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.823589 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:36.836844 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.837327 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:36.999722 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.162s	user 0.108s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":9593,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29834,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:37.000324 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:37.044762 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.044s	user 0.008s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19643,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.045542 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:37.210636 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.165s	user 0.102s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":147,"lbm_read_time_us":11889,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25382,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:18:37.211354 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:37.267103 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.056s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23080,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.267607 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:37.279209 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.279691 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:37.474656 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.195s	user 0.140s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":13217,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31185,"lbm_writes_lt_1ms":543,"mutex_wait_us":340,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:37.475455 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:37.523851 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21413,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.524508 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:37.537415 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.537959 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:37.702917 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.165s	user 0.120s	sys 0.039s 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":1114,"lbm_read_time_us":9364,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33209,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:18:37.703424 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=14.095187
I20260812 06:18:37.755506 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.052s	user 0.042s	sys 0.003s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21168,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.756035 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=2.188937
I20260812 06:18:37.767423 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.767889 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:37.800928 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushMRSOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1529,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:37.801663 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling LogGCOp(f21d7f9403a14bf7918ba85017bebfff): free 129320732 bytes of WAL
I20260812 06:18:37.801901 26358 log_reader.cc:385] T f21d7f9403a14bf7918ba85017bebfff: removed 13 log segments from log reader
I20260812 06:18:37.801963 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000027 (ops 131-135)
I20260812 06:18:37.802017 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000028 (ops 136-140)
I20260812 06:18:37.802075 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000029 (ops 141-145)
I20260812 06:18:37.802115 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000030 (ops 146-150)
I20260812 06:18:37.802153 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000031 (ops 151-155)
I20260812 06:18:37.802189 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000032 (ops 156-160)
I20260812 06:18:37.802227 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000033 (ops 161-165)
I20260812 06:18:37.802263 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000034 (ops 166-170)
I20260812 06:18:37.802317 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000035 (ops 171-174)
I20260812 06:18:37.802359 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000036 (ops 175-179)
I20260812 06:18:37.802397 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000037 (ops 180-184)
I20260812 06:18:37.802433 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000038 (ops 185-188)
I20260812 06:18:37.802469 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000039 (ops 189-193)
I20260812 06:18:37.833055 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: LogGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:37.833465 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff): 493 bytes on disk
I20260812 06:18:37.833889 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: UndoDeltaBlockGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.834561 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff): perf score=6.157687
I20260812 06:18:37.863694 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: FlushDeltaMemStoresOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.029s	user 0.022s	sys 0.001s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":9097,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:37.864480 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling LogGCOp(f21d7f9403a14bf7918ba85017bebfff): free 12018006 bytes of WAL
I20260812 06:18:37.864758 26358 log_reader.cc:385] T f21d7f9403a14bf7918ba85017bebfff: removed 1 log segments from log reader
I20260812 06:18:37.864826 26358 log.cc:1079] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: Deleting log segment in path: /tmp/dist-test-taskSZpmA3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507290555-25895-0/minicluster-data/ts-0-root/wals/f21d7f9403a14bf7918ba85017bebfff/wal-000000040 (ops 194-198)
I20260812 06:18:37.867940 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: LogGCOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:37.868297 26450 maintenance_manager.cc:419] P 62ae26746c7a4e4782d86ab72c3a0794: Scheduling MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff): perf score=1.000000
I20260812 06:18:37.892830 25895 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.899s	user 1.871s	sys 0.140s
I20260812 06:18:37.993396 25895 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.100s	user 0.001s	sys 0.000s
I20260812 06:18:37.994067 25895 tablet_server.cc:179] TabletServer@127.25.73.193:0 shutting down...
I20260812 06:18:38.073860 26358 maintenance_manager.cc:643] P 62ae26746c7a4e4782d86ab72c3a0794: MajorDeltaCompactionOp(f21d7f9403a14bf7918ba85017bebfff) complete. Timing: real 0.205s	user 0.138s	sys 0.065s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1146,"lbm_read_time_us":16592,"lbm_reads_lt_1ms":761,"lbm_write_time_us":34651,"lbm_writes_lt_1ms":743,"mutex_wait_us":49,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":44800,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:18:38.074623 25895 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.075027 25895 tablet_replica.cc:333] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794: stopping tablet replica
I20260812 06:18:38.075177 25895 raft_consensus.cc:2243] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.075409 25895 raft_consensus.cc:2272] T f21d7f9403a14bf7918ba85017bebfff P 62ae26746c7a4e4782d86ab72c3a0794 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.079401 25895 tablet_server.cc:196] TabletServer@127.25.73.193:0 shutdown complete.
I20260812 06:18:38.129727 25895 master.cc:562] Master@127.25.73.254:40801 shutting down...
I20260812 06:18:38.133682 25895 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.133850 25895 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.133900 25895 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0dd7af38b5744c62bfb9f8c0d8acf04d: stopping tablet replica
I20260812 06:18:38.146148 25895 master.cc:584] Master@127.25.73.254:40801 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5459 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10933 ms total)

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