[==========] 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:40.694761  3051 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.250.254:34981
I20260812 06:18:40.695813  3051 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:40.696408  3051 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.702543  3061 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.702522  3057 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:40.702761  3051 server_base.cc:1061] running on GCE node
W20260812 06:18:40.702797  3058 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:40.703361  3051 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.703457  3051 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:40.703501  3051 hybrid_clock.cc:648] HybridClock initialized: now 1786515520703499 us; error 0 us; skew 500 ppm
I20260812 06:18:40.705247  3051 webserver.cc:533] Webserver started at http://127.2.250.254:35113/ using document root <none> and password file <none>
I20260812 06:18:40.705783  3051 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.705852  3051 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.706086  3051 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.707779  3051 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/master-0-root/instance:
uuid: "eefd1b186c9c4346874bc5d0c4b01970"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nj21"
I20260812 06:18:40.711145  3051 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:40.713166  3074 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:40.714119  3051 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:40.714224  3051 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/master-0-root
uuid: "eefd1b186c9c4346874bc5d0c4b01970"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nj21"
I20260812 06:18:40.714310  3051 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-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:40.732324  3051 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.732954  3051 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:40.733107  3051 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.740137  3161 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.250.254:34981 every 8 connection(s)
I20260812 06:18:40.740142  3051 rpc_server.cc:307] RPC server started. Bound to: 127.2.250.254:34981
I20260812 06:18:40.742388  3163 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:40.747857  3163 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: Bootstrap starting.
I20260812 06:18:40.750216  3163 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.751081  3163 log.cc:826] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:40.752750  3163 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: No bootstrap required, opened a new log
I20260812 06:18:40.755486  3163 raft_consensus.cc:359] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER }
I20260812 06:18:40.755649  3163 raft_consensus.cc:385] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.755753  3163 raft_consensus.cc:740] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eefd1b186c9c4346874bc5d0c4b01970, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.756343  3163 consensus_queue.cc:260] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [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: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER }
I20260812 06:18:40.756500  3163 raft_consensus.cc:399] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.756565  3163 raft_consensus.cc:493] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.756683  3163 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.757444  3163 raft_consensus.cc:515] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER }
I20260812 06:18:40.757870  3163 leader_election.cc:304] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [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: eefd1b186c9c4346874bc5d0c4b01970; no voters: 
I20260812 06:18:40.758172  3163 leader_election.cc:290] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.758294  3167 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.758509  3167 raft_consensus.cc:697] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 1 LEADER]: Becoming Leader. State: Replica: eefd1b186c9c4346874bc5d0c4b01970, State: Running, Role: LEADER
I20260812 06:18:40.758916  3167 consensus_queue.cc:237] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [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: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER }
I20260812 06:18:40.759119  3163 sys_catalog.cc:565] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.760735  3168 sys_catalog.cc:455] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eefd1b186c9c4346874bc5d0c4b01970" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER } }
I20260812 06:18:40.760722  3172 sys_catalog.cc:455] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [sys.catalog]: SysCatalogTable state changed. Reason: New leader eefd1b186c9c4346874bc5d0c4b01970. Latest consensus state: current_term: 1 leader_uuid: "eefd1b186c9c4346874bc5d0c4b01970" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eefd1b186c9c4346874bc5d0c4b01970" member_type: VOTER } }
I20260812 06:18:40.760869  3172 sys_catalog.cc:458] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.760869  3168 sys_catalog.cc:458] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.761291  3051 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.761307  3191 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.763447  3191 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.768124  3191 catalog_manager.cc:1383] Generated new cluster ID: 07717fa9738d47ab9d41ca1bf8074a85
I20260812 06:18:40.768188  3191 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.787070  3191 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.788337  3191 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.800074  3191 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: Generated new TSK 0
I20260812 06:18:40.800853  3191 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.826129  3051 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.828750  3198 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:40.828889  3199 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:40.828959  3051 server_base.cc:1061] running on GCE node
W20260812 06:18:40.829079  3201 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:40.829303  3051 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.829365  3051 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:40.829387  3051 hybrid_clock.cc:648] HybridClock initialized: now 1786515520829387 us; error 0 us; skew 500 ppm
I20260812 06:18:40.830327  3051 webserver.cc:533] Webserver started at http://127.2.250.193:40299/ using document root <none> and password file <none>
I20260812 06:18:40.830494  3051 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.830550  3051 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.830624  3051 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.831061  3051 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/instance:
uuid: "5ff21d19b93e4d34b8dd79945acaf43b"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nj21"
I20260812 06:18:40.832897  3051 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:40.833976  3211 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:40.834235  3051 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:40.834311  3051 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root
uuid: "5ff21d19b93e4d34b8dd79945acaf43b"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nj21"
I20260812 06:18:40.834389  3051 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-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:40.864248  3051 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.864706  3051 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.865192  3051 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.866088  3051 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.866144  3051 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.866202  3051 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.866245  3051 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.872746  3051 rpc_server.cc:307] RPC server started. Bound to: 127.2.250.193:33655
I20260812 06:18:40.872816  3331 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.250.193:33655 every 8 connection(s)
I20260812 06:18:40.882355  3332 heartbeater.cc:344] Connected to a master server at 127.2.250.254:34981
I20260812 06:18:40.882586  3332 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.883024  3332 heartbeater.cc:507] Master 127.2.250.254:34981 requested a full tablet report, sending...
I20260812 06:18:40.884387  3102 ts_manager.cc:194] Registered new tserver with Master: 5ff21d19b93e4d34b8dd79945acaf43b (127.2.250.193:33655)
I20260812 06:18:40.884572  3051 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011184898s
I20260812 06:18:40.885864  3102 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39322
I20260812 06:18:40.893630  3102 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39332:
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:40.906648  3253 tablet_service.cc:1511] Processing CreateTablet for tablet 6312789dacd9477fa8320d9da1c971bf (DEFAULT_TABLE table=heavy-update-compaction-test [id=668b3a1d3bbd4da996894698d042dda9]), partition=
I20260812 06:18:40.907070  3253 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6312789dacd9477fa8320d9da1c971bf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.909436  3352 tablet_bootstrap.cc:492] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Bootstrap starting.
I20260812 06:18:40.910624  3352 tablet_bootstrap.cc:654] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.911886  3352 tablet_bootstrap.cc:492] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: No bootstrap required, opened a new log
I20260812 06:18:40.911972  3352 ts_tablet_manager.cc:1403] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:40.912396  3352 raft_consensus.cc:359] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ff21d19b93e4d34b8dd79945acaf43b" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 33655 } }
I20260812 06:18:40.912492  3352 raft_consensus.cc:385] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.912515  3352 raft_consensus.cc:740] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5ff21d19b93e4d34b8dd79945acaf43b, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.912642  3352 consensus_queue.cc:260] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [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: "5ff21d19b93e4d34b8dd79945acaf43b" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 33655 } }
I20260812 06:18:40.912710  3352 raft_consensus.cc:399] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.912746  3352 raft_consensus.cc:493] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.912794  3352 raft_consensus.cc:3060] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.913441  3352 raft_consensus.cc:515] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ff21d19b93e4d34b8dd79945acaf43b" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 33655 } }
I20260812 06:18:40.913561  3352 leader_election.cc:304] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [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: 5ff21d19b93e4d34b8dd79945acaf43b; no voters: 
I20260812 06:18:40.913748  3352 leader_election.cc:290] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.913858  3357 raft_consensus.cc:2804] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.914059  3352 ts_tablet_manager.cc:1434] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:40.914119  3357 raft_consensus.cc:697] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 1 LEADER]: Becoming Leader. State: Replica: 5ff21d19b93e4d34b8dd79945acaf43b, State: Running, Role: LEADER
I20260812 06:18:40.914268  3332 heartbeater.cc:499] Master 127.2.250.254:34981 was elected leader, sending a full tablet report...
I20260812 06:18:40.914288  3357 consensus_queue.cc:237] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [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: "5ff21d19b93e4d34b8dd79945acaf43b" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 33655 } }
I20260812 06:18:40.917021  3102 catalog_manager.cc:5719] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b reported cstate change: term changed from 0 to 1, leader changed from <none> to 5ff21d19b93e4d34b8dd79945acaf43b (127.2.250.193). New cstate: current_term: 1 leader_uuid: "5ff21d19b93e4d34b8dd79945acaf43b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ff21d19b93e4d34b8dd79945acaf43b" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 33655 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.971306  3051 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.018s	sys 0.004s
I20260812 06:18:41.123915  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushMRSOp(6312789dacd9477fa8320d9da1c971bf): perf score=19.054940
I20260812 06:18:41.277472  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushMRSOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.153s	user 0.122s	sys 0.028s Metrics: {"bytes_written":8697369,"cfile_init":1,"compiler_manager_pool.queue_time_us":244,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":737,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38841,"lbm_writes_lt_1ms":769,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":158,"threads_started":1,"update_count":1060}
I20260812 06:18:41.278599  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling LogGCOp(6312789dacd9477fa8320d9da1c971bf): free 20743880 bytes of WAL
I20260812 06:18:41.278952  3217 log_reader.cc:385] T 6312789dacd9477fa8320d9da1c971bf: removed 2 log segments from log reader
I20260812 06:18:41.279018  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000001 (ops 1-6)
I20260812 06:18:41.279074  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000002 (ops 7-11)
I20260812 06:18:41.282545  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: LogGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:41.283021  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf): 20513812 bytes on disk
I20260812 06:18:41.283706  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.284219  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:41.300302  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:18:41.300839  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:41.424304  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.123s	user 0.068s	sys 0.045s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16610847,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":410,"lbm_read_time_us":6008,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21606,"lbm_writes_lt_1ms":343,"mutex_wait_us":36,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":279,"threads_started":5,"update_count":1500}
I20260812 06:18:41.424763  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:41.465655  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.041s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12973,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.466156  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:41.476150  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.476613  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:41.607306  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.130s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1214,"lbm_read_time_us":9278,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22846,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:41.607849  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:41.639993  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.032s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13489,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.640481  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:41.767726  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.127s	user 0.082s	sys 0.043s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1038,"lbm_read_time_us":8553,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21049,"lbm_writes_lt_1ms":343,"mutex_wait_us":1420,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":1500}
I20260812 06:18:41.768332  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:41.806612  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16399,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.807116  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:41.818902  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.819306  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:41.941524  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.122s	user 0.096s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":8197,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:41.942003  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:41.985857  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.044s	user 0.009s	sys 0.025s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.986380  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.001821  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.002367  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:42.113221  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.111s	user 0.086s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":484,"lbm_read_time_us":6901,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22226,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:42.113692  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:42.147374  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.034s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13346,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.147832  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.157500  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.158118  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:42.274541  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.116s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":121,"lbm_read_time_us":7689,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23043,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:42.275017  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:42.320662  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.045s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.321272  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.336472  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.336982  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:42.470211  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.133s	user 0.098s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":9754,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21961,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:18:42.470818  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:42.517657  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.047s	user 0.008s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.518121  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.527832  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.528419  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushMRSOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:42.556213  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushMRSOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1427,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1570,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:42.557363  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling LogGCOp(6312789dacd9477fa8320d9da1c971bf): free 120553322 bytes of WAL
I20260812 06:18:42.557617  3217 log_reader.cc:385] T 6312789dacd9477fa8320d9da1c971bf: removed 12 log segments from log reader
I20260812 06:18:42.557677  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000003 (ops 12-16)
I20260812 06:18:42.557720  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000004 (ops 17-21)
I20260812 06:18:42.557793  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000005 (ops 22-26)
I20260812 06:18:42.557832  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000006 (ops 27-31)
I20260812 06:18:42.557868  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000007 (ops 32-36)
I20260812 06:18:42.557910  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000008 (ops 37-41)
I20260812 06:18:42.557946  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000009 (ops 42-46)
I20260812 06:18:42.557982  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000010 (ops 47-50)
I20260812 06:18:42.558017  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000011 (ops 51-55)
I20260812 06:18:42.558051  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000012 (ops 56-60)
I20260812 06:18:42.558087  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000013 (ops 61-64)
I20260812 06:18:42.558121  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000014 (ops 65-69)
I20260812 06:18:42.579737  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: LogGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:42.580174  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf): 472 bytes on disk
I20260812 06:18:42.580637  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.581173  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=3.181125
I20260812 06:18:42.600445  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4636,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.600992  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.614956  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.615520  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:42.811918  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.196s	user 0.118s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":633,"lbm_read_time_us":13463,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31188,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:42.812521  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=14.095187
I20260812 06:18:42.867925  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21222,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.868408  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:42.878321  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.878780  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.031252  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.152s	user 0.080s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":12249,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24938,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2500}
I20260812 06:18:43.031790  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.065387  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.033s	user 0.008s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12701,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.066015  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.081110  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.081743  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.205662  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.124s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":8903,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22596,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:43.206240  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.245563  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.039s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14782,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.246147  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.259853  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.260308  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.380370  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":56,"lbm_read_time_us":6625,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23653,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:43.381501  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.412734  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.031s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14402,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.413266  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.426369  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5160,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.426908  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.542858  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.116s	user 0.103s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":7096,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20878,"lbm_writes_lt_1ms":443,"mutex_wait_us":353,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:43.543871  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.586853  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15840,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.587551  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.597795  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.598394  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.743409  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.145s	user 0.114s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":966,"lbm_read_time_us":10087,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22669,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:18:43.744050  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.785534  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.041s	user 0.025s	sys 0.006s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14066,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.786063  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.801754  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.802474  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:43.923363  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.121s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":314,"lbm_read_time_us":7721,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23396,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:43.924003  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=10.126437
I20260812 06:18:43.960544  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.036s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.961117  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:43.972039  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.972545  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushMRSOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:44.001300  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushMRSOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.029s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":991,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1609,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:44.002068  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling LogGCOp(6312789dacd9477fa8320d9da1c971bf): free 133477498 bytes of WAL
I20260812 06:18:44.002318  3217 log_reader.cc:385] T 6312789dacd9477fa8320d9da1c971bf: removed 13 log segments from log reader
I20260812 06:18:44.002389  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000015 (ops 70-74)
I20260812 06:18:44.002435  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000016 (ops 75-79)
I20260812 06:18:44.002466  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000017 (ops 80-84)
I20260812 06:18:44.002501  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000018 (ops 85-89)
I20260812 06:18:44.002530  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000019 (ops 90-94)
I20260812 06:18:44.002558  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000020 (ops 95-99)
I20260812 06:18:44.002588  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000021 (ops 100-104)
I20260812 06:18:44.002616  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000022 (ops 105-109)
I20260812 06:18:44.002648  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000023 (ops 110-114)
I20260812 06:18:44.002679  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000024 (ops 115-119)
I20260812 06:18:44.002707  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000025 (ops 120-124)
I20260812 06:18:44.002734  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000026 (ops 125-129)
I20260812 06:18:44.002763  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000027 (ops 130-134)
I20260812 06:18:44.029086  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: LogGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:44.029568  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=3.181125
I20260812 06:18:44.041534  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.041980  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:44.051785  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.052253  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:44.221493  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.169s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":643,"lbm_read_time_us":10955,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33677,"lbm_writes_lt_1ms":643,"mutex_wait_us":259,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:44.222045  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=14.095187
I20260812 06:18:44.264868  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17996,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.265411  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:44.277751  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.278290  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:44.425766  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.147s	user 0.116s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":9312,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29307,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:44.426831  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf): 483 bytes on disk
I20260812 06:18:44.427415  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.428190  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=12.110812
I20260812 06:18:44.491449  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.063s	user 0.025s	sys 0.020s Metrics: {"bytes_written":14235626,"delete_count":0,"lbm_write_time_us":23504,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":349,"reinsert_count":0,"update_count":1735}
I20260812 06:18:44.492041  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=5.165500
I20260812 06:18:44.512683  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.020s	user 0.014s	sys 0.004s Metrics: {"bytes_written":6276951,"delete_count":0,"lbm_write_time_us":7522,"lbm_writes_lt_1ms":156,"reinsert_count":0,"update_count":765}
I20260812 06:18:44.513173  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:44.664206  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.151s	user 0.098s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815694,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":9581,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26957,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:18:44.664749  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=14.095187
I20260812 06:18:44.719089  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.054s	user 0.017s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19257,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.719694  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:44.729933  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.730422  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:44.900725  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.170s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":703,"lbm_read_time_us":10813,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28539,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:44.901361  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=14.095187
I20260812 06:18:44.959882  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.058s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21894,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.960582  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:44.970954  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.971436  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:45.136843  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.165s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":11270,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26938,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":58112,"update_count":2500}
I20260812 06:18:45.137387  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=14.095187
I20260812 06:18:45.192886  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.055s	user 0.030s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.193581  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:45.204239  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.204712  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:45.371695  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.167s	user 0.106s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":11619,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30569,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.372292  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=11.118625
I20260812 06:18:45.405061  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.032s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13885,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.405629  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=2.188937
I20260812 06:18:45.424396  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7137,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.424857  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushMRSOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:45.467361  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushMRSOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.042s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1396,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2300,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:45.468120  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling LogGCOp(6312789dacd9477fa8320d9da1c971bf): free 132571593 bytes of WAL
I20260812 06:18:45.468351  3217 log_reader.cc:385] T 6312789dacd9477fa8320d9da1c971bf: removed 13 log segments from log reader
I20260812 06:18:45.468400  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000028 (ops 135-138)
I20260812 06:18:45.468429  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000029 (ops 139-143)
I20260812 06:18:45.468463  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000030 (ops 144-148)
I20260812 06:18:45.468489  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000031 (ops 149-153)
I20260812 06:18:45.468521  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000032 (ops 154-158)
I20260812 06:18:45.468551  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000033 (ops 159-162)
I20260812 06:18:45.468585  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000034 (ops 163-167)
I20260812 06:18:45.468616  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000035 (ops 168-172)
I20260812 06:18:45.468648  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000036 (ops 173-177)
I20260812 06:18:45.468680  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000037 (ops 178-182)
I20260812 06:18:45.468711  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000038 (ops 183-187)
I20260812 06:18:45.468743  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000039 (ops 188-192)
I20260812 06:18:45.468776  3217 log.cc:1079] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/6312789dacd9477fa8320d9da1c971bf/wal-000000040 (ops 193-197)
I20260812 06:18:45.493578  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: LogGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:45.493984  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf): 492 bytes on disk
I20260812 06:18:45.494431  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: UndoDeltaBlockGCOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.494975  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf): perf score=6.157687
I20260812 06:18:45.515161  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: FlushDeltaMemStoresOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8386,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:45.515703  3336 maintenance_manager.cc:419] P 5ff21d19b93e4d34b8dd79945acaf43b: Scheduling MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf): perf score=1.000000
I20260812 06:18:45.530895  3051 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.559s	user 1.694s	sys 0.108s
I20260812 06:18:45.607729  3051 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.004s	sys 0.000s
I20260812 06:18:45.608378  3051 tablet_server.cc:179] TabletServer@127.2.250.193:0 shutting down...
I20260812 06:18:45.670621  3217 maintenance_manager.cc:643] P 5ff21d19b93e4d34b8dd79945acaf43b: MajorDeltaCompactionOp(6312789dacd9477fa8320d9da1c971bf) complete. Timing: real 0.155s	user 0.114s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918209,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2000,"lbm_read_time_us":10909,"lbm_reads_lt_1ms":665,"lbm_write_time_us":26335,"lbm_writes_lt_1ms":643,"mutex_wait_us":1486,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":68096,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:45.671288  3051 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:45.671705  3051 tablet_replica.cc:333] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b: stopping tablet replica
I20260812 06:18:45.671923  3051 raft_consensus.cc:2243] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.672164  3051 raft_consensus.cc:2272] T 6312789dacd9477fa8320d9da1c971bf P 5ff21d19b93e4d34b8dd79945acaf43b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.692288  3051 tablet_server.cc:196] TabletServer@127.2.250.193:0 shutdown complete.
I20260812 06:18:45.720125  3051 master.cc:562] Master@127.2.250.254:34981 shutting down...
I20260812 06:18:45.723654  3051 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.723871  3051 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.723954  3051 tablet_replica.cc:333] T 00000000000000000000000000000000 P eefd1b186c9c4346874bc5d0c4b01970: stopping tablet replica
I20260812 06:18:45.736240  3051 master.cc:584] Master@127.2.250.254:34981 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5111 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:45.816751  3051 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.250.254:38491
I20260812 06:18:45.817175  3051 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.819114  3399 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:45.819209  3404 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:45.819211  3406 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:45.819423  3051 server_base.cc:1061] running on GCE node
I20260812 06:18:45.819622  3051 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.819662  3051 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:45.819705  3051 hybrid_clock.cc:648] HybridClock initialized: now 1786515525819703 us; error 0 us; skew 500 ppm
I20260812 06:18:45.820504  3051 webserver.cc:533] Webserver started at http://127.2.250.254:35297/ using document root <none> and password file <none>
I20260812 06:18:45.820642  3051 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.820683  3051 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.820737  3051 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.821080  3051 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/master-0-root/instance:
uuid: "cd256227f4544abeae7b5b47d07e8e94"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-nj21"
I20260812 06:18:45.822484  3051 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:45.823359  3417 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:45.823602  3051 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:45.823665  3051 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/master-0-root
uuid: "cd256227f4544abeae7b5b47d07e8e94"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-nj21"
I20260812 06:18:45.823762  3051 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-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:45.832407  3051 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.832717  3051 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.836664  3051 rpc_server.cc:307] RPC server started. Bound to: 127.2.250.254:38491
I20260812 06:18:45.841512  3515 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.250.254:38491 every 8 connection(s)
I20260812 06:18:45.842067  3516 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:45.843958  3516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94: Bootstrap starting.
I20260812 06:18:45.844717  3516 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.845698  3516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94: No bootstrap required, opened a new log
I20260812 06:18:45.846110  3516 raft_consensus.cc:359] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER }
I20260812 06:18:45.846196  3516 raft_consensus.cc:385] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.846223  3516 raft_consensus.cc:740] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd256227f4544abeae7b5b47d07e8e94, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.846329  3516 consensus_queue.cc:260] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [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: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER }
I20260812 06:18:45.846386  3516 raft_consensus.cc:399] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.846412  3516 raft_consensus.cc:493] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.846446  3516 raft_consensus.cc:3060] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.847100  3516 raft_consensus.cc:515] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER }
I20260812 06:18:45.847219  3516 leader_election.cc:304] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [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: cd256227f4544abeae7b5b47d07e8e94; no voters: 
I20260812 06:18:45.847358  3516 leader_election.cc:290] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.847491  3525 raft_consensus.cc:2804] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.847741  3525 raft_consensus.cc:697] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 1 LEADER]: Becoming Leader. State: Replica: cd256227f4544abeae7b5b47d07e8e94, State: Running, Role: LEADER
I20260812 06:18:45.847843  3516 sys_catalog.cc:565] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:45.847905  3525 consensus_queue.cc:237] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [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: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER }
I20260812 06:18:45.848331  3527 sys_catalog.cc:455] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "cd256227f4544abeae7b5b47d07e8e94" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER } }
I20260812 06:18:45.848366  3530 sys_catalog.cc:455] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [sys.catalog]: SysCatalogTable state changed. Reason: New leader cd256227f4544abeae7b5b47d07e8e94. Latest consensus state: current_term: 1 leader_uuid: "cd256227f4544abeae7b5b47d07e8e94" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd256227f4544abeae7b5b47d07e8e94" member_type: VOTER } }
I20260812 06:18:45.848517  3530 sys_catalog.cc:458] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.848501  3527 sys_catalog.cc:458] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.849066  3540 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:45.849835  3540 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:45.850032  3051 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:45.851612  3540 catalog_manager.cc:1383] Generated new cluster ID: 5f45d824fb65483683c9c0cc0ecbbf42
I20260812 06:18:45.851688  3540 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:45.856004  3540 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:45.856510  3540 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:45.864475  3540 catalog_manager.cc:6092] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94: Generated new TSK 0
I20260812 06:18:45.864655  3540 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:45.866101  3051 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.867961  3567 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:45.867966  3570 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:45.868116  3562 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:45.868116  3051 server_base.cc:1061] running on GCE node
I20260812 06:18:45.868480  3051 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.868523  3051 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:45.868544  3051 hybrid_clock.cc:648] HybridClock initialized: now 1786515525868544 us; error 0 us; skew 500 ppm
I20260812 06:18:45.869379  3051 webserver.cc:533] Webserver started at http://127.2.250.193:35865/ using document root <none> and password file <none>
I20260812 06:18:45.869556  3051 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.869611  3051 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.869697  3051 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.870077  3051 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/instance:
uuid: "46727b6b1fba46f9953ea7e182be4d02"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-nj21"
I20260812 06:18:45.871523  3051 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:45.872517  3578 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:45.872763  3051 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:45.872835  3051 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root
uuid: "46727b6b1fba46f9953ea7e182be4d02"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-nj21"
I20260812 06:18:45.872910  3051 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-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:45.907598  3051 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.908053  3051 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.908362  3051 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:45.908834  3051 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:45.908874  3051 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.908921  3051 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:45.908947  3051 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.913010  3051 rpc_server.cc:307] RPC server started. Bound to: 127.2.250.193:38475
I20260812 06:18:45.913050  3696 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.250.193:38475 every 8 connection(s)
I20260812 06:18:45.921144  3699 heartbeater.cc:344] Connected to a master server at 127.2.250.254:38491
I20260812 06:18:45.921262  3699 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:45.921538  3699 heartbeater.cc:507] Master 127.2.250.254:38491 requested a full tablet report, sending...
I20260812 06:18:45.922200  3450 ts_manager.cc:194] Registered new tserver with Master: 46727b6b1fba46f9953ea7e182be4d02 (127.2.250.193:38475)
I20260812 06:18:45.922281  3051 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008843662s
I20260812 06:18:45.923007  3450 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40542
I20260812 06:18:45.929136  3450 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40556:
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:45.938195  3629 tablet_service.cc:1511] Processing CreateTablet for tablet 64cc347b816545bd8f4593829a1308fe (DEFAULT_TABLE table=heavy-update-compaction-test [id=158192a283a4454baa3f2a0fe3d7e407]), partition=
I20260812 06:18:45.938467  3629 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 64cc347b816545bd8f4593829a1308fe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:45.940603  3721 tablet_bootstrap.cc:492] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Bootstrap starting.
I20260812 06:18:45.941429  3721 tablet_bootstrap.cc:654] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.942448  3721 tablet_bootstrap.cc:492] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: No bootstrap required, opened a new log
I20260812 06:18:45.942525  3721 ts_tablet_manager.cc:1403] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:45.942991  3721 raft_consensus.cc:359] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46727b6b1fba46f9953ea7e182be4d02" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 38475 } }
I20260812 06:18:45.943084  3721 raft_consensus.cc:385] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.943105  3721 raft_consensus.cc:740] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 46727b6b1fba46f9953ea7e182be4d02, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.943403  3721 consensus_queue.cc:260] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [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: "46727b6b1fba46f9953ea7e182be4d02" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 38475 } }
I20260812 06:18:45.943499  3721 raft_consensus.cc:399] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.943543  3721 raft_consensus.cc:493] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.943588  3721 raft_consensus.cc:3060] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.944306  3721 raft_consensus.cc:515] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46727b6b1fba46f9953ea7e182be4d02" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 38475 } }
I20260812 06:18:45.944429  3721 leader_election.cc:304] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [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: 46727b6b1fba46f9953ea7e182be4d02; no voters: 
I20260812 06:18:45.944583  3721 leader_election.cc:290] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.944690  3724 raft_consensus.cc:2804] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.944882  3721 ts_tablet_manager.cc:1434] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Time spent starting tablet: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:18:45.944903  3699 heartbeater.cc:499] Master 127.2.250.254:38491 was elected leader, sending a full tablet report...
I20260812 06:18:45.944914  3724 raft_consensus.cc:697] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 1 LEADER]: Becoming Leader. State: Replica: 46727b6b1fba46f9953ea7e182be4d02, State: Running, Role: LEADER
I20260812 06:18:45.945076  3724 consensus_queue.cc:237] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [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: "46727b6b1fba46f9953ea7e182be4d02" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 38475 } }
I20260812 06:18:45.946376  3450 catalog_manager.cc:5719] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 reported cstate change: term changed from 0 to 1, leader changed from <none> to 46727b6b1fba46f9953ea7e182be4d02 (127.2.250.193). New cstate: current_term: 1 leader_uuid: "46727b6b1fba46f9953ea7e182be4d02" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "46727b6b1fba46f9953ea7e182be4d02" member_type: VOTER last_known_addr { host: "127.2.250.193" port: 38475 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:46.004891  3051 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:18:46.163964  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushMRSOp(64cc347b816545bd8f4593829a1308fe): perf score=23.023690
I20260812 06:18:46.331250  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushMRSOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.167s	user 0.125s	sys 0.036s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":769,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41663,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:46.332069  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling LogGCOp(64cc347b816545bd8f4593829a1308fe): free 20743880 bytes of WAL
I20260812 06:18:46.332315  3583 log_reader.cc:385] T 64cc347b816545bd8f4593829a1308fe: removed 2 log segments from log reader
I20260812 06:18:46.332379  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000001 (ops 1-6)
I20260812 06:18:46.332427  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000002 (ops 7-11)
I20260812 06:18:46.337263  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: LogGCOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:46.337699  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:46.349159  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.349647  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe): 20513814 bytes on disk
I20260812 06:18:46.350066  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.350539  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:46.497465  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.147s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":462,"lbm_read_time_us":9186,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24655,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":324,"threads_started":5,"update_count":2000}
I20260812 06:18:46.498107  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=11.118625
I20260812 06:18:46.534129  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.036s	user 0.033s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15505,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.534587  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:46.552253  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5274,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.552816  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:46.706260  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.153s	user 0.102s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1019,"lbm_read_time_us":11600,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22676,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53120,"update_count":2000}
I20260812 06:18:46.706885  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:46.748206  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19188,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.748903  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:46.773634  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.774230  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:46.785419  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.786128  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:46.946022  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.160s	user 0.114s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":656,"lbm_read_time_us":9817,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26794,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:18:46.946563  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:46.991952  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.045s	user 0.018s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":15990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.992446  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.002626  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.003269  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:47.143846  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.140s	user 0.119s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":9034,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27690,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:47.145614  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:47.177901  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13612,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.178385  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.190275  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.190794  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:47.306736  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.116s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":820,"lbm_read_time_us":8346,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21849,"lbm_writes_lt_1ms":443,"mutex_wait_us":257,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:18:47.307274  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:47.357321  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.050s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20148,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.357914  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.368522  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.369045  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:47.513528  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.144s	user 0.084s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":841,"lbm_read_time_us":10517,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23769,"lbm_writes_lt_1ms":443,"mutex_wait_us":243,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:18:47.514051  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:47.552747  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.039s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13590,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.553216  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.563191  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.563755  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushMRSOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:47.594239  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushMRSOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":34,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1231,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2101,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:47.594901  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling LogGCOp(64cc347b816545bd8f4593829a1308fe): free 128414386 bytes of WAL
I20260812 06:18:47.595134  3583 log_reader.cc:385] T 64cc347b816545bd8f4593829a1308fe: removed 13 log segments from log reader
I20260812 06:18:47.595181  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000003 (ops 12-16)
I20260812 06:18:47.595218  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000004 (ops 17-20)
I20260812 06:18:47.595255  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000005 (ops 21-25)
I20260812 06:18:47.595288  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000006 (ops 26-30)
I20260812 06:18:47.595319  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000007 (ops 31-34)
I20260812 06:18:47.595347  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000008 (ops 35-39)
I20260812 06:18:47.595376  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000009 (ops 40-44)
I20260812 06:18:47.595407  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000010 (ops 45-48)
I20260812 06:18:47.595436  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000011 (ops 49-53)
I20260812 06:18:47.595474  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000012 (ops 54-58)
I20260812 06:18:47.595504  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000013 (ops 59-63)
I20260812 06:18:47.595533  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000014 (ops 64-68)
I20260812 06:18:47.595563  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000015 (ops 69-72)
I20260812 06:18:47.617762  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: LogGCOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:47.618257  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe): 472 bytes on disk
I20260812 06:18:47.618695  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe) 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:47.619140  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=3.181125
I20260812 06:18:47.646189  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.027s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4639,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.646833  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.660663  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5081,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.661167  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:47.844271  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.183s	user 0.134s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":582,"lbm_read_time_us":13639,"lbm_reads_lt_1ms":674,"lbm_write_time_us":27980,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19456,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:47.844844  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:47.897045  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.052s	user 0.019s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.897642  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:47.912765  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.913260  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:48.087844  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.174s	user 0.114s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":742,"lbm_read_time_us":12135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29616,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:48.088559  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=11.118625
I20260812 06:18:48.126215  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15885,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.126747  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.146453  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4375,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.146936  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.168156  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.021s	user 0.014s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.168700  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:48.342483  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.174s	user 0.114s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":182,"lbm_read_time_us":12279,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27479,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.343025  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:48.385648  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.042s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17339,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.386211  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.397387  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.398041  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:48.574162  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.176s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":415,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26378,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:18:48.574644  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:48.619887  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.045s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16636,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.620450  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.636067  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.636708  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:48.779068  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.142s	user 0.122s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":9194,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28498,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:18:48.780038  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=11.118625
I20260812 06:18:48.809906  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.030s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11974,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.810457  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.835813  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.025s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5064,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.836313  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:48.846490  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.846961  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:48.987043  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.140s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":465,"lbm_read_time_us":9438,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27777,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:18:48.987699  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:49.015606  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.028s	user 0.012s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11691,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.016252  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:49.029846  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.030375  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushMRSOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:49.073688  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushMRSOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.043s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1116,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1687,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:49.074535  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling LogGCOp(64cc347b816545bd8f4593829a1308fe): free 121006392 bytes of WAL
I20260812 06:18:49.074790  3583 log_reader.cc:385] T 64cc347b816545bd8f4593829a1308fe: removed 12 log segments from log reader
I20260812 06:18:49.074842  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000016 (ops 73-77)
I20260812 06:18:49.074887  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000017 (ops 78-82)
I20260812 06:18:49.074919  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000018 (ops 83-86)
I20260812 06:18:49.074954  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000019 (ops 87-91)
I20260812 06:18:49.074985  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000020 (ops 92-96)
I20260812 06:18:49.075018  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000021 (ops 97-101)
I20260812 06:18:49.075050  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000022 (ops 102-106)
I20260812 06:18:49.075083  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000023 (ops 107-111)
I20260812 06:18:49.075119  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000024 (ops 112-116)
I20260812 06:18:49.075151  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000025 (ops 117-121)
I20260812 06:18:49.075183  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000026 (ops 122-126)
I20260812 06:18:49.075212  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000027 (ops 127-131)
I20260812 06:18:49.100665  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: LogGCOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:49.101128  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=3.181125
I20260812 06:18:49.118212  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":5210311,"delete_count":0,"lbm_write_time_us":7084,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 06:18:49.118655  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe): 482 bytes on disk
I20260812 06:18:49.119050  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: UndoDeltaBlockGCOp(64cc347b816545bd8f4593829a1308fe) 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:49.119545  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=1.196750
I20260812 06:18:49.129606  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":2956,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:18:49.130054  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:49.293488  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.163s	user 0.112s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918307,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1232,"lbm_read_time_us":11420,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33700,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:49.294034  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:49.339955  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.046s	user 0.014s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.340655  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:49.352854  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.353559  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:49.511499  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.158s	user 0.126s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":938,"lbm_read_time_us":10839,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27874,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":146304,"update_count":2500}
I20260812 06:18:49.512096  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:49.551499  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.039s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17333,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.552078  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:49.708120  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.156s	user 0.105s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":280,"lbm_read_time_us":8368,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24565,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:49.708670  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:49.754186  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.045s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20588,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.754762  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:49.768537  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.014s	user 0.000s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.769018  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:49.932998  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.164s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":670,"lbm_read_time_us":10676,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26133,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:49.933557  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:49.982028  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.048s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18724,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.982549  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:49.993199  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.993759  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:50.136718  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.143s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":11558,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27252,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:50.137212  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=10.126437
I20260812 06:18:50.183993  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.047s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.184711  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:50.208655  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.209161  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:50.220439  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.221211  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:50.384281  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.163s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815805,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":355,"lbm_read_time_us":12234,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29755,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:50.384781  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=14.095187
I20260812 06:18:50.427361  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.042s	user 0.028s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17112,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.428022  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=2.188937
I20260812 06:18:50.438654  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.439314  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushMRSOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:50.472015  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushMRSOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1452,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1481,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:50.472671  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling LogGCOp(64cc347b816545bd8f4593829a1308fe): free 133024706 bytes of WAL
I20260812 06:18:50.472886  3583 log_reader.cc:385] T 64cc347b816545bd8f4593829a1308fe: removed 13 log segments from log reader
I20260812 06:18:50.472930  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000028 (ops 132-136)
I20260812 06:18:50.472959  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000029 (ops 137-141)
I20260812 06:18:50.472990  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000030 (ops 142-146)
I20260812 06:18:50.473021  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000031 (ops 147-151)
I20260812 06:18:50.473052  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000032 (ops 152-156)
I20260812 06:18:50.473083  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000033 (ops 157-161)
I20260812 06:18:50.473114  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000034 (ops 162-166)
I20260812 06:18:50.473145  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000035 (ops 167-170)
I20260812 06:18:50.473174  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000036 (ops 171-175)
I20260812 06:18:50.473204  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000037 (ops 176-180)
I20260812 06:18:50.473234  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000038 (ops 181-185)
I20260812 06:18:50.473272  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000039 (ops 186-190)
I20260812 06:18:50.473304  3583 log.cc:1079] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: Deleting log segment in path: /tmp/dist-test-taskiXrves/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520684114-3051-0/minicluster-data/ts-0-root/wals/64cc347b816545bd8f4593829a1308fe/wal-000000040 (ops 191-195)
I20260812 06:18:50.497531  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: LogGCOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:50.497910  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=4.173312
I20260812 06:18:50.511620  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5948752,"delete_count":0,"lbm_write_time_us":5529,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:18:50.512076  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe): perf score=1.196750
I20260812 06:18:50.518703  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: FlushDeltaMemStoresOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":2145,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:18:50.519272  3700 maintenance_manager.cc:419] P 46727b6b1fba46f9953ea7e182be4d02: Scheduling MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe): perf score=1.000000
I20260812 06:18:50.557700  3051 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.553s	user 1.669s	sys 0.166s
I20260812 06:18:50.655951  3051 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.004s	sys 0.000s
I20260812 06:18:50.656558  3051 tablet_server.cc:179] TabletServer@127.2.250.193:0 shutting down...
I20260812 06:18:50.718089  3583 maintenance_manager.cc:643] P 46727b6b1fba46f9953ea7e182be4d02: MajorDeltaCompactionOp(64cc347b816545bd8f4593829a1308fe) complete. Timing: real 0.199s	user 0.108s	sys 0.086s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020701,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":801,"lbm_read_time_us":13970,"lbm_reads_lt_1ms":770,"lbm_write_time_us":31056,"lbm_writes_lt_1ms":743,"mutex_wait_us":72,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:18:50.718998  3051 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:50.719353  3051 tablet_replica.cc:333] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02: stopping tablet replica
I20260812 06:18:50.719528  3051 raft_consensus.cc:2243] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:50.719702  3051 raft_consensus.cc:2272] T 64cc347b816545bd8f4593829a1308fe P 46727b6b1fba46f9953ea7e182be4d02 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:50.734289  3051 tablet_server.cc:196] TabletServer@127.2.250.193:0 shutdown complete.
I20260812 06:18:50.775305  3051 master.cc:562] Master@127.2.250.254:38491 shutting down...
I20260812 06:18:50.778441  3051 raft_consensus.cc:2243] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:50.778631  3051 raft_consensus.cc:2272] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:50.778705  3051 tablet_replica.cc:333] T 00000000000000000000000000000000 P cd256227f4544abeae7b5b47d07e8e94: stopping tablet replica
I20260812 06:18:50.791077  3051 master.cc:584] Master@127.2.250.254:38491 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5053 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10166 ms total)

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