[==========] 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:16.879122  5349 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.57.126:33765
I20260812 06:18:16.880132  5349 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:16.880684  5349 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:16.886838  5359 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:16.886878  5349 server_base.cc:1061] running on GCE node
W20260812 06:18:16.886941  5358 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:16.887156  5361 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:16.887567  5349 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:16.887655  5349 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:16.887682  5349 hybrid_clock.cc:648] HybridClock initialized: now 1786515496887681 us; error 0 us; skew 500 ppm
I20260812 06:18:16.889303  5349 webserver.cc:533] Webserver started at http://127.5.57.126:38227/ using document root <none> and password file <none>
I20260812 06:18:16.889776  5349 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:16.889829  5349 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:16.890010  5349 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:16.891490  5349 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/master-0-root/instance:
uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-bndk"
I20260812 06:18:16.894603  5349 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.005s
I20260812 06:18:16.896662  5367 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:16.897612  5349 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:16.897711  5349 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/master-0-root
uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-bndk"
I20260812 06:18:16.897790  5349 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-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:16.908017  5349 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:16.908500  5349 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:16.908635  5349 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:16.915445  5452 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.57.126:33765 every 8 connection(s)
I20260812 06:18:16.915452  5349 rpc_server.cc:307] RPC server started. Bound to: 127.5.57.126:33765
I20260812 06:18:16.917474  5454 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:16.922300  5454 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: Bootstrap starting.
I20260812 06:18:16.924305  5454 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:16.925068  5454 log.cc:826] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:16.926482  5454 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: No bootstrap required, opened a new log
I20260812 06:18:16.928913  5454 raft_consensus.cc:359] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER }
I20260812 06:18:16.929061  5454 raft_consensus.cc:385] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:16.929104  5454 raft_consensus.cc:740] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fa8ae0b387f846b4958a5bf92ca1f7c4, State: Initialized, Role: FOLLOWER
I20260812 06:18:16.929621  5454 consensus_queue.cc:260] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [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: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER }
I20260812 06:18:16.929751  5454 raft_consensus.cc:399] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:16.929795  5454 raft_consensus.cc:493] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:16.929874  5454 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:16.930505  5454 raft_consensus.cc:515] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER }
I20260812 06:18:16.930840  5454 leader_election.cc:304] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [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: fa8ae0b387f846b4958a5bf92ca1f7c4; no voters: 
I20260812 06:18:16.931068  5454 leader_election.cc:290] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:16.931174  5458 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:16.931399  5458 raft_consensus.cc:697] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 1 LEADER]: Becoming Leader. State: Replica: fa8ae0b387f846b4958a5bf92ca1f7c4, State: Running, Role: LEADER
I20260812 06:18:16.931720  5458 consensus_queue.cc:237] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [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: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER }
I20260812 06:18:16.931854  5454 sys_catalog.cc:565] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:16.933380  5459 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER } }
I20260812 06:18:16.933411  5460 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader fa8ae0b387f846b4958a5bf92ca1f7c4. Latest consensus state: current_term: 1 leader_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa8ae0b387f846b4958a5bf92ca1f7c4" member_type: VOTER } }
I20260812 06:18:16.933493  5459 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:16.933498  5460 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:16.933840  5477 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:16.933964  5349 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:16.935998  5477 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:16.939949  5477 catalog_manager.cc:1383] Generated new cluster ID: 5fa21fefab7a478eadd1bdb888eddd47
I20260812 06:18:16.940006  5477 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:16.959937  5477 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:16.960903  5477 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:16.967510  5477 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: Generated new TSK 0
I20260812 06:18:16.968104  5477 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:16.998795  5349 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.001256  5492 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:17.001359  5498 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:17.001271  5493 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:17.001565  5349 server_base.cc:1061] running on GCE node
I20260812 06:18:17.001724  5349 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.001762  5349 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:17.001782  5349 hybrid_clock.cc:648] HybridClock initialized: now 1786515497001782 us; error 0 us; skew 500 ppm
I20260812 06:18:17.002607  5349 webserver.cc:533] Webserver started at http://127.5.57.65:42825/ using document root <none> and password file <none>
I20260812 06:18:17.002761  5349 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.002810  5349 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.002882  5349 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.003232  5349 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/instance:
uuid: "38ef43fd80de4e8e86189c46a2c6d0ea"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-bndk"
I20260812 06:18:17.004601  5349 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:17.005509  5510 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:17.005718  5349 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:17.005785  5349 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root
uuid: "38ef43fd80de4e8e86189c46a2c6d0ea"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-bndk"
I20260812 06:18:17.005847  5349 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-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:17.053359  5349 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.053812  5349 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.054236  5349 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:17.055073  5349 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:17.055125  5349 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.055182  5349 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:17.055214  5349 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.061250  5349 rpc_server.cc:307] RPC server started. Bound to: 127.5.57.65:38701
I20260812 06:18:17.061344  5618 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.57.65:38701 every 8 connection(s)
I20260812 06:18:17.074476  5619 heartbeater.cc:344] Connected to a master server at 127.5.57.126:33765
I20260812 06:18:17.074672  5619 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:17.075073  5619 heartbeater.cc:507] Master 127.5.57.126:33765 requested a full tablet report, sending...
I20260812 06:18:17.076643  5394 ts_manager.cc:194] Registered new tserver with Master: 38ef43fd80de4e8e86189c46a2c6d0ea (127.5.57.65:38701)
I20260812 06:18:17.077333  5349 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015457866s
I20260812 06:18:17.078176  5394 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55022
I20260812 06:18:17.086253  5394 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55030:
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:17.098328  5557 tablet_service.cc:1511] Processing CreateTablet for tablet dda534e8398a4dbcbd41a771e01c5f99 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2b93e779cd7f4f2abb847dce805ef7dd]), partition=
I20260812 06:18:17.098714  5557 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dda534e8398a4dbcbd41a771e01c5f99. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:17.100867  5638 tablet_bootstrap.cc:492] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Bootstrap starting.
I20260812 06:18:17.101694  5638 tablet_bootstrap.cc:654] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.102674  5638 tablet_bootstrap.cc:492] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: No bootstrap required, opened a new log
I20260812 06:18:17.102828  5638 ts_tablet_manager.cc:1403] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:17.103214  5638 raft_consensus.cc:359] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38ef43fd80de4e8e86189c46a2c6d0ea" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 38701 } }
I20260812 06:18:17.103336  5638 raft_consensus.cc:385] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.103372  5638 raft_consensus.cc:740] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 38ef43fd80de4e8e86189c46a2c6d0ea, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.103487  5638 consensus_queue.cc:260] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [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: "38ef43fd80de4e8e86189c46a2c6d0ea" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 38701 } }
I20260812 06:18:17.103559  5638 raft_consensus.cc:399] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.103595  5638 raft_consensus.cc:493] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.103638  5638 raft_consensus.cc:3060] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.104482  5638 raft_consensus.cc:515] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38ef43fd80de4e8e86189c46a2c6d0ea" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 38701 } }
I20260812 06:18:17.104621  5638 leader_election.cc:304] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [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: 38ef43fd80de4e8e86189c46a2c6d0ea; no voters: 
I20260812 06:18:17.104806  5638 leader_election.cc:290] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.104907  5641 raft_consensus.cc:2804] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.105100  5641 raft_consensus.cc:697] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 1 LEADER]: Becoming Leader. State: Replica: 38ef43fd80de4e8e86189c46a2c6d0ea, State: Running, Role: LEADER
I20260812 06:18:17.105136  5638 ts_tablet_manager.cc:1434] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:17.105470  5619 heartbeater.cc:499] Master 127.5.57.126:33765 was elected leader, sending a full tablet report...
I20260812 06:18:17.105526  5641 consensus_queue.cc:237] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [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: "38ef43fd80de4e8e86189c46a2c6d0ea" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 38701 } }
I20260812 06:18:17.107865  5394 catalog_manager.cc:5719] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea reported cstate change: term changed from 0 to 1, leader changed from <none> to 38ef43fd80de4e8e86189c46a2c6d0ea (127.5.57.65). New cstate: current_term: 1 leader_uuid: "38ef43fd80de4e8e86189c46a2c6d0ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "38ef43fd80de4e8e86189c46a2c6d0ea" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 38701 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:17.162518  5349 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.020s	sys 0.003s
I20260812 06:18:17.312249  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=23.023690
I20260812 06:18:17.490404  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.178s	user 0.128s	sys 0.040s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":220,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":829,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42977,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":136,"threads_started":1,"update_count":1500}
I20260812 06:18:17.491496  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling LogGCOp(dda534e8398a4dbcbd41a771e01c5f99): free 20743880 bytes of WAL
I20260812 06:18:17.491801  5518 log_reader.cc:385] T dda534e8398a4dbcbd41a771e01c5f99: removed 2 log segments from log reader
I20260812 06:18:17.491861  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000001 (ops 1-6)
I20260812 06:18:17.491914  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000002 (ops 7-11)
I20260812 06:18:17.495538  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: LogGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:17.495859  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99): 20513842 bytes on disk
I20260812 06:18:17.496392  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.496800  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:17.506925  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.507340  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:17.648877  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.141s	user 0.101s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":808,"lbm_read_time_us":9584,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23069,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":263,"threads_started":5,"update_count":2000}
I20260812 06:18:17.649449  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:17.691747  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.042s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12585,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.692211  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:17.705353  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.705969  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:17.823114  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.117s	user 0.094s	sys 0.022s 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":809,"lbm_read_time_us":9733,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20587,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:17.823570  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:17.868575  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.045s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19308,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.869096  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:17.880273  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.880872  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:17.992139  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.111s	user 0.094s	sys 0.017s 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":208,"lbm_read_time_us":7037,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20846,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:17.992688  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:18.034528  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.042s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15308,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.035044  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:18.044795  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.045248  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:18.186708  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.141s	user 0.081s	sys 0.055s 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":481,"lbm_read_time_us":9561,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23765,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:18:18.187186  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:18.230763  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.043s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18195,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.231199  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:18.240993  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.241515  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:18.350567  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.109s	user 0.075s	sys 0.033s 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":163,"lbm_read_time_us":7417,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19834,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:18.351023  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:18.393610  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17850,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.394299  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:18.409818  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.410315  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:18.536474  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.126s	user 0.110s	sys 0.016s 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":788,"lbm_read_time_us":8829,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24382,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.537057  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:18.591112  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.054s	user 0.033s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21876,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.591724  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:18.605381  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.605850  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:18.636792  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1325,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1910,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:18.637741  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling LogGCOp(dda534e8398a4dbcbd41a771e01c5f99): free 120553372 bytes of WAL
I20260812 06:18:18.637984  5518 log_reader.cc:385] T dda534e8398a4dbcbd41a771e01c5f99: removed 12 log segments from log reader
I20260812 06:18:18.638036  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000003 (ops 12-16)
I20260812 06:18:18.638082  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000004 (ops 17-21)
I20260812 06:18:18.638115  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000005 (ops 22-26)
I20260812 06:18:18.638146  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000006 (ops 27-31)
I20260812 06:18:18.638180  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000007 (ops 32-36)
I20260812 06:18:18.638211  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000008 (ops 37-40)
I20260812 06:18:18.638242  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000009 (ops 41-45)
I20260812 06:18:18.638271  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000010 (ops 46-50)
I20260812 06:18:18.638302  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000011 (ops 51-55)
I20260812 06:18:18.638332  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000012 (ops 56-60)
I20260812 06:18:18.638404  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000013 (ops 61-64)
I20260812 06:18:18.638430  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000014 (ops 65-69)
I20260812 06:18:18.659935  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: LogGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:18.660360  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=3.181125
I20260812 06:18:18.684031  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:18.684454  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99): 447 bytes on disk
I20260812 06:18:18.684857  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.685343  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:18.694288  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3331,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.694726  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:18.885639  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.191s	user 0.107s	sys 0.079s 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":1734,"lbm_read_time_us":12850,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31326,"lbm_writes_lt_1ms":643,"mutex_wait_us":1317,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:18.886065  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=14.095187
I20260812 06:18:18.925859  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.040s	user 0.035s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17318,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.926350  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.058753  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.132s	user 0.085s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713155,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":772,"lbm_read_time_us":9885,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20401,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:18:19.059301  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:19.090538  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.031s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.091112  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.109386  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.018s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.109818  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.228571  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.119s	user 0.082s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":8773,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21736,"lbm_writes_lt_1ms":443,"mutex_wait_us":231,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:19.229135  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:19.263737  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.034s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15643,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.264309  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.282548  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.018s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.283067  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.411556  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.128s	user 0.113s	sys 0.015s 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":170,"lbm_read_time_us":9348,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24934,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.412096  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=10.126437
I20260812 06:18:19.450469  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.038s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.450982  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.467447  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.016s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.467990  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.588835  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.121s	user 0.070s	sys 0.045s 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":714,"lbm_read_time_us":8190,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20906,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:19.589398  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=11.118625
I20260812 06:18:19.630596  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.041s	user 0.029s	sys 0.006s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14727,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.631155  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.654966  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.024s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:19.655438  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.668495  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":4986,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:19.668927  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.841833  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.173s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":181,"lbm_read_time_us":11860,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28108,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":63360,"update_count":2500}
I20260812 06:18:19.842355  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=14.095187
I20260812 06:18:19.899010  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.057s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18560,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.899562  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:19.909492  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.909945  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:19.937465  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.027s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1308,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1347,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:19.938283  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:20.076737  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.138s	user 0.090s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":9312,"lbm_reads_lt_1ms":564,"lbm_write_time_us":23224,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:20.077327  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling LogGCOp(dda534e8398a4dbcbd41a771e01c5f99): free 108535462 bytes of WAL
I20260812 06:18:20.077565  5518 log_reader.cc:385] T dda534e8398a4dbcbd41a771e01c5f99: removed 11 log segments from log reader
I20260812 06:18:20.077627  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000015 (ops 70-74)
I20260812 06:18:20.077718  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000016 (ops 75-79)
I20260812 06:18:20.077762  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000017 (ops 80-84)
I20260812 06:18:20.077785  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000018 (ops 85-88)
I20260812 06:18:20.077841  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000019 (ops 89-93)
I20260812 06:18:20.077877  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000020 (ops 94-98)
I20260812 06:18:20.077908  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000021 (ops 99-102)
I20260812 06:18:20.077937  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000022 (ops 103-107)
I20260812 06:18:20.077991  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000023 (ops 108-112)
I20260812 06:18:20.078027  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000024 (ops 113-117)
I20260812 06:18:20.078059  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000025 (ops 118-122)
I20260812 06:18:20.101899  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: LogGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.024s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:20.102375  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=15.087375
I20260812 06:18:20.154251  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.052s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20290,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:20.154767  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99): 448 bytes on disk
I20260812 06:18:20.155360  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.155975  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.174914  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.019s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.175315  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.184137  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3281,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.184568  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:20.357358  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.173s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":351,"lbm_read_time_us":12501,"lbm_reads_lt_1ms":673,"lbm_write_time_us":28796,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":3000}
I20260812 06:18:20.357916  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=14.095187
I20260812 06:18:20.408057  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.050s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22346,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.408562  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.419222  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.419612  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:20.592586  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.173s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":771,"lbm_read_time_us":11062,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32320,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:20.593101  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=14.095187
I20260812 06:18:20.642552  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.049s	user 0.017s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.643054  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.654165  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.654577  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:20.824141  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.169s	user 0.102s	sys 0.064s 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":559,"lbm_read_time_us":12081,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27649,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32640,"update_count":2500}
I20260812 06:18:20.824707  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=11.118625
I20260812 06:18:20.860810  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15132,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:20.861418  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.890123  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.029s	user 0.006s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.890663  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:20.900467  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.900880  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:21.072538  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.172s	user 0.104s	sys 0.056s 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":350,"lbm_read_time_us":11389,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25658,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:21.073108  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=14.095187
I20260812 06:18:21.116753  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.043s	user 0.019s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19989,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.117260  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:21.132396  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.133127  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:21.288481  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.155s	user 0.107s	sys 0.045s 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":312,"lbm_read_time_us":10702,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23549,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:21.289070  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=11.118625
I20260812 06:18:21.324323  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14761,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.324857  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:21.337482  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3558,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.338049  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:21.375994  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushMRSOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.038s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":316,"dirs.run_wall_time_us":1340,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1406,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:21.376672  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99): 482 bytes on disk
I20260812 06:18:21.377154  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: UndoDeltaBlockGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.377769  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=3.181125
I20260812 06:18:21.399443  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.022s	user 0.008s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3893,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:21.399978  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling LogGCOp(dda534e8398a4dbcbd41a771e01c5f99): free 136275428 bytes of WAL
I20260812 06:18:21.400233  5518 log_reader.cc:385] T dda534e8398a4dbcbd41a771e01c5f99: removed 13 log segments from log reader
I20260812 06:18:21.400296  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000026 (ops 123-127)
I20260812 06:18:21.400342  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000027 (ops 128-132)
I20260812 06:18:21.400372  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000028 (ops 133-137)
I20260812 06:18:21.400401  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000029 (ops 138-142)
I20260812 06:18:21.400435  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000030 (ops 143-147)
I20260812 06:18:21.400463  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000031 (ops 148-152)
I20260812 06:18:21.400491  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000032 (ops 153-157)
I20260812 06:18:21.400511  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000033 (ops 158-162)
I20260812 06:18:21.400538  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000034 (ops 163-167)
I20260812 06:18:21.400570  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000035 (ops 168-172)
I20260812 06:18:21.400600  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000036 (ops 173-176)
I20260812 06:18:21.400627  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000037 (ops 177-181)
I20260812 06:18:21.400655  5518 log.cc:1079] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/dda534e8398a4dbcbd41a771e01c5f99/wal-000000038 (ops 182-186)
I20260812 06:18:21.430238  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: LogGCOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:21.430660  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:21.443562  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.013s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.444002  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:21.632357  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.188s	user 0.134s	sys 0.044s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29328568,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1180,"lbm_read_time_us":11267,"lbm_reads_lt_1ms":676,"lbm_write_time_us":31332,"lbm_writes_lt_1ms":653,"mutex_wait_us":255,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":75,"threads_started":1,"update_count":3050}
I20260812 06:18:21.632942  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=18.063937
I20260812 06:18:21.703099  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.070s	user 0.050s	sys 0.018s Metrics: {"bytes_written":20102073,"delete_count":0,"lbm_write_time_us":26845,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:18:21.703595  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=2.188937
I20260812 06:18:21.718065  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: FlushDeltaMemStoresOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.014s	user 0.000s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.718601  5620 maintenance_manager.cc:419] P 38ef43fd80de4e8e86189c46a2c6d0ea: Scheduling MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99): perf score=1.000000
I20260812 06:18:21.760808  5349 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.598s	user 1.652s	sys 0.170s
I20260812 06:18:21.841809  5349 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.003s	sys 0.000s
I20260812 06:18:21.842422  5349 tablet_server.cc:179] TabletServer@127.5.57.65:0 shutting down...
I20260812 06:18:21.882174  5518 maintenance_manager.cc:643] P 38ef43fd80de4e8e86189c46a2c6d0ea: MajorDeltaCompactionOp(dda534e8398a4dbcbd41a771e01c5f99) complete. Timing: real 0.163s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28507855,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":12333,"lbm_reads_lt_1ms":658,"lbm_write_time_us":30163,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":632,"mutex_wait_us":21,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2950}
I20260812 06:18:21.882923  5349 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:21.883325  5349 tablet_replica.cc:333] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea: stopping tablet replica
I20260812 06:18:21.883553  5349 raft_consensus.cc:2243] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:21.883759  5349 raft_consensus.cc:2272] T dda534e8398a4dbcbd41a771e01c5f99 P 38ef43fd80de4e8e86189c46a2c6d0ea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:21.900363  5349 tablet_server.cc:196] TabletServer@127.5.57.65:0 shutdown complete.
I20260812 06:18:21.933804  5349 master.cc:562] Master@127.5.57.126:33765 shutting down...
I20260812 06:18:21.937366  5349 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:21.937534  5349 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:21.937611  5349 tablet_replica.cc:333] T 00000000000000000000000000000000 P fa8ae0b387f846b4958a5bf92ca1f7c4: stopping tablet replica
I20260812 06:18:21.949658  5349 master.cc:584] Master@127.5.57.126:33765 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5145 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:22.029634  5349 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.57.126:45311
I20260812 06:18:22.030014  5349 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.031839  5668 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:22.031942  5670 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:22.031999  5349 server_base.cc:1061] running on GCE node
W20260812 06:18:22.032083  5667 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:22.032259  5349 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.032334  5349 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:22.032356  5349 hybrid_clock.cc:648] HybridClock initialized: now 1786515502032355 us; error 0 us; skew 500 ppm
I20260812 06:18:22.033053  5349 webserver.cc:533] Webserver started at http://127.5.57.126:46877/ using document root <none> and password file <none>
I20260812 06:18:22.033196  5349 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.033265  5349 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.033350  5349 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.033703  5349 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/master-0-root/instance:
uuid: "44d600de75444980af18f3c3f32c87d8"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-bndk"
I20260812 06:18:22.035152  5349 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:22.036005  5680 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:22.036203  5349 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:22.036273  5349 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/master-0-root
uuid: "44d600de75444980af18f3c3f32c87d8"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-bndk"
I20260812 06:18:22.036343  5349 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-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:22.048218  5349 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.048540  5349 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.052615  5349 rpc_server.cc:307] RPC server started. Bound to: 127.5.57.126:45311
I20260812 06:18:22.056875  5776 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.57.126:45311 every 8 connection(s)
I20260812 06:18:22.057328  5778 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:22.058996  5778 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8: Bootstrap starting.
I20260812 06:18:22.059712  5778 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.060608  5778 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8: No bootstrap required, opened a new log
I20260812 06:18:22.060992  5778 raft_consensus.cc:359] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER }
I20260812 06:18:22.061098  5778 raft_consensus.cc:385] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.061131  5778 raft_consensus.cc:740] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 44d600de75444980af18f3c3f32c87d8, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.061291  5778 consensus_queue.cc:260] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [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: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER }
I20260812 06:18:22.061378  5778 raft_consensus.cc:399] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.061414  5778 raft_consensus.cc:493] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.061462  5778 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.062093  5778 raft_consensus.cc:515] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER }
I20260812 06:18:22.062215  5778 leader_election.cc:304] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [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: 44d600de75444980af18f3c3f32c87d8; no voters: 
I20260812 06:18:22.062383  5778 leader_election.cc:290] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.062490  5784 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.062673  5784 raft_consensus.cc:697] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 1 LEADER]: Becoming Leader. State: Replica: 44d600de75444980af18f3c3f32c87d8, State: Running, Role: LEADER
I20260812 06:18:22.062777  5778 sys_catalog.cc:565] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:22.062816  5784 consensus_queue.cc:237] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [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: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER }
I20260812 06:18:22.063225  5787 sys_catalog.cc:455] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 44d600de75444980af18f3c3f32c87d8. Latest consensus state: current_term: 1 leader_uuid: "44d600de75444980af18f3c3f32c87d8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER } }
I20260812 06:18:22.063211  5786 sys_catalog.cc:455] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "44d600de75444980af18f3c3f32c87d8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44d600de75444980af18f3c3f32c87d8" member_type: VOTER } }
I20260812 06:18:22.063315  5787 sys_catalog.cc:458] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.063325  5786 sys_catalog.cc:458] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.063567  5793 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:22.064468  5793 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:22.064626  5349 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:22.066180  5793 catalog_manager.cc:1383] Generated new cluster ID: e3bab33b774440949e2fb639ac0c8070
I20260812 06:18:22.066234  5793 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:22.088796  5793 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:22.089330  5793 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:22.097189  5793 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8: Generated new TSK 0
I20260812 06:18:22.097354  5793 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:22.128971  5349 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.130759  5815 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:22.130892  5816 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:22.130913  5349 server_base.cc:1061] running on GCE node
W20260812 06:18:22.130822  5818 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:22.131176  5349 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.131229  5349 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:22.131245  5349 hybrid_clock.cc:648] HybridClock initialized: now 1786515502131245 us; error 0 us; skew 500 ppm
I20260812 06:18:22.132068  5349 webserver.cc:533] Webserver started at http://127.5.57.65:35951/ using document root <none> and password file <none>
I20260812 06:18:22.132215  5349 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.132267  5349 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.132341  5349 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.132704  5349 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/instance:
uuid: "030984621eb14673bc3f581d7abebedc"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-bndk"
I20260812 06:18:22.134114  5349 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:22.134939  5826 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:22.135195  5349 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:22.135262  5349 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root
uuid: "030984621eb14673bc3f581d7abebedc"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-bndk"
I20260812 06:18:22.135326  5349 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-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:22.142060  5349 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.142347  5349 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.142603  5349 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:22.143006  5349 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:22.143044  5349 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.143082  5349 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:22.143110  5349 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.147197  5349 rpc_server.cc:307] RPC server started. Bound to: 127.5.57.65:46245
I20260812 06:18:22.147627  5943 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.57.65:46245 every 8 connection(s)
I20260812 06:18:22.154465  5944 heartbeater.cc:344] Connected to a master server at 127.5.57.126:45311
I20260812 06:18:22.154560  5944 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:22.154757  5944 heartbeater.cc:507] Master 127.5.57.126:45311 requested a full tablet report, sending...
I20260812 06:18:22.155335  5714 ts_manager.cc:194] Registered new tserver with Master: 030984621eb14673bc3f581d7abebedc (127.5.57.65:46245)
I20260812 06:18:22.155378  5349 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007661907s
I20260812 06:18:22.156015  5714 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48288
I20260812 06:18:22.161330  5714 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48290:
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:22.169656  5869 tablet_service.cc:1511] Processing CreateTablet for tablet 3190f81a92054863993580f822649924 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3a2cca96fa7847a880370f7c2155d410]), partition=
I20260812 06:18:22.169904  5869 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3190f81a92054863993580f822649924. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.171864  5962 tablet_bootstrap.cc:492] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Bootstrap starting.
I20260812 06:18:22.172653  5962 tablet_bootstrap.cc:654] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.173599  5962 tablet_bootstrap.cc:492] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: No bootstrap required, opened a new log
I20260812 06:18:22.173671  5962 ts_tablet_manager.cc:1403] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:22.174015  5962 raft_consensus.cc:359] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "030984621eb14673bc3f581d7abebedc" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 46245 } }
I20260812 06:18:22.174093  5962 raft_consensus.cc:385] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.174113  5962 raft_consensus.cc:740] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 030984621eb14673bc3f581d7abebedc, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.174213  5962 consensus_queue.cc:260] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [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: "030984621eb14673bc3f581d7abebedc" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 46245 } }
I20260812 06:18:22.174299  5962 raft_consensus.cc:399] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.174328  5962 raft_consensus.cc:493] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.174364  5962 raft_consensus.cc:3060] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.175177  5962 raft_consensus.cc:515] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "030984621eb14673bc3f581d7abebedc" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 46245 } }
I20260812 06:18:22.175290  5962 leader_election.cc:304] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [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: 030984621eb14673bc3f581d7abebedc; no voters: 
I20260812 06:18:22.175438  5962 leader_election.cc:290] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.175561  5964 raft_consensus.cc:2804] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.175742  5962 ts_tablet_manager.cc:1434] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:22.175770  5964 raft_consensus.cc:697] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 1 LEADER]: Becoming Leader. State: Replica: 030984621eb14673bc3f581d7abebedc, State: Running, Role: LEADER
I20260812 06:18:22.175800  5944 heartbeater.cc:499] Master 127.5.57.126:45311 was elected leader, sending a full tablet report...
I20260812 06:18:22.175904  5964 consensus_queue.cc:237] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [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: "030984621eb14673bc3f581d7abebedc" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 46245 } }
I20260812 06:18:22.177122  5714 catalog_manager.cc:5719] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc reported cstate change: term changed from 0 to 1, leader changed from <none> to 030984621eb14673bc3f581d7abebedc (127.5.57.65). New cstate: current_term: 1 leader_uuid: "030984621eb14673bc3f581d7abebedc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "030984621eb14673bc3f581d7abebedc" member_type: VOTER last_known_addr { host: "127.5.57.65" port: 46245 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:22.228387  5349 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.017s	sys 0.004s
I20260812 06:18:22.398290  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushMRSOp(3190f81a92054863993580f822649924): perf score=23.023690
I20260812 06:18:22.558184  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushMRSOp(3190f81a92054863993580f822649924) complete. Timing: real 0.160s	user 0.133s	sys 0.024s Metrics: {"bytes_written":14563816,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":145,"dirs.run_wall_time_us":804,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44405,"lbm_writes_lt_1ms":912,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1775}
I20260812 06:18:22.558883  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=1.196750
I20260812 06:18:22.574054  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.015s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2748838,"delete_count":0,"lbm_write_time_us":2523,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:18:22.574565  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling LogGCOp(3190f81a92054863993580f822649924): free 20743880 bytes of WAL
I20260812 06:18:22.574793  5833 log_reader.cc:385] T 3190f81a92054863993580f822649924: removed 2 log segments from log reader
I20260812 06:18:22.574852  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000001 (ops 1-6)
I20260812 06:18:22.574890  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000002 (ops 7-11)
I20260812 06:18:22.580343  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: LogGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:22.580637  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:22.589327  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3039,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:22.589690  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:22.752579  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.163s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815754,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":438,"lbm_read_time_us":10123,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27098,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":288,"threads_started":5,"update_count":2500}
I20260812 06:18:22.753078  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:22.804217  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.051s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17391,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.804653  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling UndoDeltaBlockGCOp(3190f81a92054863993580f822649924): 20513811 bytes on disk
I20260812 06:18:22.805085  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: UndoDeltaBlockGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.805529  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:22.814812  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.815151  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:22.988715  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.173s	user 0.109s	sys 0.064s 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":992,"lbm_read_time_us":12507,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27128,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:22.989177  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:23.035272  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.046s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21961,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.035820  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:23.184855  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.149s	user 0.092s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":624,"lbm_read_time_us":11019,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22582,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:23.185459  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:23.230104  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.044s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21951,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.230528  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:23.253101  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.022s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.253669  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:23.437723  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.184s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31327,"lbm_writes_lt_1ms":543,"mutex_wait_us":136,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:23.438251  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:23.485683  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.047s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20080,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.486222  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:23.503942  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.504479  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:23.649359  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.145s	user 0.114s	sys 0.024s 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":332,"lbm_read_time_us":8582,"lbm_reads_lt_1ms":564,"lbm_write_time_us":23791,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:23.649899  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:23.702190  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.052s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21148,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.702732  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:23.713630  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.011s	user 0.010s	sys 0.000s 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:23.714134  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushMRSOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:23.743971  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushMRSOp(3190f81a92054863993580f822649924) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1250,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1498,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:23.744520  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling LogGCOp(3190f81a92054863993580f822649924): free 121006444 bytes of WAL
I20260812 06:18:23.744740  5833 log_reader.cc:385] T 3190f81a92054863993580f822649924: removed 12 log segments from log reader
I20260812 06:18:23.744783  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000003 (ops 12-16)
I20260812 06:18:23.744812  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000004 (ops 17-21)
I20260812 06:18:23.744828  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000005 (ops 22-26)
I20260812 06:18:23.744855  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000006 (ops 27-31)
I20260812 06:18:23.744884  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000007 (ops 32-36)
I20260812 06:18:23.744921  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000008 (ops 37-41)
I20260812 06:18:23.744954  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000009 (ops 42-46)
I20260812 06:18:23.744977  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000010 (ops 47-50)
I20260812 06:18:23.745005  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000011 (ops 51-55)
I20260812 06:18:23.745028  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000012 (ops 56-60)
I20260812 06:18:23.745059  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000013 (ops 61-65)
I20260812 06:18:23.745081  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000014 (ops 66-70)
I20260812 06:18:23.767930  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: LogGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.023s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:18:23.768323  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling UndoDeltaBlockGCOp(3190f81a92054863993580f822649924): 462 bytes on disk
I20260812 06:18:23.768747  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: UndoDeltaBlockGCOp(3190f81a92054863993580f822649924) 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:23.769248  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=4.173312
I20260812 06:18:23.796344  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.027s	user 0.012s	sys 0.012s Metrics: {"bytes_written":6153869,"delete_count":0,"lbm_write_time_us":7293,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:18:23.796773  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:23.805303  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.008s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2952,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:18:23.805653  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:24.015944  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.210s	user 0.142s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":152,"lbm_read_time_us":15107,"lbm_reads_lt_1ms":774,"lbm_write_time_us":34975,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:18:24.019366  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=15.087375
I20260812 06:18:24.059434  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":17538,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:24.059911  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:24.072244  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.072717  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:24.232321  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.159s	user 0.094s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815671,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1579,"lbm_read_time_us":11616,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25543,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:18:24.232939  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:24.285588  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.052s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18339,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.286105  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:24.300606  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.301069  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:24.479688  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.178s	user 0.117s	sys 0.054s 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":152,"lbm_read_time_us":12699,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28338,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:24.480240  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:24.543270  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.063s	user 0.029s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.543794  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:24.553805  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.554246  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:24.723644  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.169s	user 0.110s	sys 0.052s 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":109,"lbm_read_time_us":11941,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26126,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:24.724450  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:24.765920  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.041s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19438,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.766404  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:24.776661  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.777256  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:24.939515  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.162s	user 0.109s	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":206,"lbm_read_time_us":9480,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25510,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:18:24.939986  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:24.983213  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.043s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.983736  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:24.998814  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.999411  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:25.142412  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.143s	user 0.123s	sys 0.015s 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":866,"lbm_read_time_us":8795,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24713,"lbm_writes_lt_1ms":543,"mutex_wait_us":222,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:25.143052  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=11.118625
I20260812 06:18:25.174881  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13287,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.175352  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:25.198525  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.199064  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:25.208508  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.209064  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushMRSOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:25.238716  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushMRSOp(3190f81a92054863993580f822649924) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":167,"dirs.run_wall_time_us":1305,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1593,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:25.239331  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling LogGCOp(3190f81a92054863993580f822649924): free 132118281 bytes of WAL
I20260812 06:18:25.239562  5833 log_reader.cc:385] T 3190f81a92054863993580f822649924: removed 13 log segments from log reader
I20260812 06:18:25.239609  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000015 (ops 71-74)
I20260812 06:18:25.239637  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000016 (ops 75-79)
I20260812 06:18:25.239671  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000017 (ops 80-84)
I20260812 06:18:25.239696  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000018 (ops 85-88)
I20260812 06:18:25.239727  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000019 (ops 89-93)
I20260812 06:18:25.239758  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000020 (ops 94-98)
I20260812 06:18:25.239787  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000021 (ops 99-103)
I20260812 06:18:25.239817  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000022 (ops 104-108)
I20260812 06:18:25.239847  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000023 (ops 109-113)
I20260812 06:18:25.239876  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000024 (ops 114-118)
I20260812 06:18:25.239907  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000025 (ops 119-123)
I20260812 06:18:25.239938  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000026 (ops 124-128)
I20260812 06:18:25.239967  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000027 (ops 129-132)
I20260812 06:18:25.263819  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: LogGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:25.264245  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling UndoDeltaBlockGCOp(3190f81a92054863993580f822649924): 493 bytes on disk
I20260812 06:18:25.264675  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: UndoDeltaBlockGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.265290  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=3.181125
I20260812 06:18:25.288055  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4594954,"delete_count":0,"lbm_write_time_us":5020,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:18:25.288498  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:25.302116  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:18:25.302522  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:25.534152  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.231s	user 0.145s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020847,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":259,"lbm_read_time_us":15668,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36480,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:18:25.534686  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=18.063937
I20260812 06:18:25.595990  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.061s	user 0.035s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24646,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.596510  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:25.607586  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.607973  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:25.795598  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.187s	user 0.107s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":12689,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31282,"lbm_writes_lt_1ms":643,"mutex_wait_us":284,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:25.796171  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=15.087375
I20260812 06:18:25.840583  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.044s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":19529,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:25.841102  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:25.853560  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4489,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.854022  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.019246  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.165s	user 0.129s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815670,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":12509,"lbm_reads_lt_1ms":564,"lbm_write_time_us":24711,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:26.019856  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:26.078614  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.059s	user 0.046s	sys 0.011s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23079,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.079186  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:26.096510  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.017s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.096941  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.262732  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.166s	user 0.105s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1202,"lbm_read_time_us":10161,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27322,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:18:26.263324  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:26.314481  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.051s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18375,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.315063  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:26.330087  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.330539  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.492872  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.162s	user 0.104s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":9387,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26554,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:26.493487  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:26.533382  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.040s	user 0.030s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.533927  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:26.548933  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.549407  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushMRSOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.576807  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushMRSOp(3190f81a92054863993580f822649924) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1295,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1701,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:26.577527  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling LogGCOp(3190f81a92054863993580f822649924): free 120553643 bytes of WAL
I20260812 06:18:26.577754  5833 log_reader.cc:385] T 3190f81a92054863993580f822649924: removed 12 log segments from log reader
I20260812 06:18:26.577816  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000028 (ops 133-137)
I20260812 06:18:26.577864  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000029 (ops 138-142)
I20260812 06:18:26.577894  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000030 (ops 143-147)
I20260812 06:18:26.577917  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000031 (ops 148-152)
I20260812 06:18:26.577948  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000032 (ops 153-157)
I20260812 06:18:26.577978  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000033 (ops 158-162)
I20260812 06:18:26.578013  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000034 (ops 163-167)
I20260812 06:18:26.578042  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000035 (ops 168-172)
I20260812 06:18:26.578070  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000036 (ops 173-176)
I20260812 06:18:26.578102  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000037 (ops 177-181)
I20260812 06:18:26.578131  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000038 (ops 182-186)
I20260812 06:18:26.578158  5833 log.cc:1079] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: Deleting log segment in path: /tmp/dist-test-taskoYYCLV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496865296-5349-0/minicluster-data/ts-0-root/wals/3190f81a92054863993580f822649924/wal-000000039 (ops 187-190)
I20260812 06:18:26.603530  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: LogGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:26.603895  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling UndoDeltaBlockGCOp(3190f81a92054863993580f822649924): 462 bytes on disk
I20260812 06:18:26.604321  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: UndoDeltaBlockGCOp(3190f81a92054863993580f822649924) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.604943  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=3.181125
I20260812 06:18:26.619890  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3795,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:26.620261  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=2.188937
I20260812 06:18:26.629029  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3437,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.629405  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.807988  5349 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.580s	user 1.673s	sys 0.154s
I20260812 06:18:26.840103  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.211s	user 0.154s	sys 0.053s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13619,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37103,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:18:26.840629  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling FlushDeltaMemStoresOp(3190f81a92054863993580f822649924): perf score=14.095187
I20260812 06:18:26.871021  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: FlushDeltaMemStoresOp(3190f81a92054863993580f822649924) complete. Timing: real 0.030s	user 0.018s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":14172,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.871565  5945 maintenance_manager.cc:419] P 030984621eb14673bc3f581d7abebedc: Scheduling MajorDeltaCompactionOp(3190f81a92054863993580f822649924): perf score=1.000000
I20260812 06:18:26.901525  5349 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.002s	sys 0.000s
I20260812 06:18:26.901983  5349 tablet_server.cc:179] TabletServer@127.5.57.65:0 shutting down...
I20260812 06:18:26.984742  5833 maintenance_manager.cc:643] P 030984621eb14673bc3f581d7abebedc: MajorDeltaCompactionOp(3190f81a92054863993580f822649924) complete. Timing: real 0.113s	user 0.096s	sys 0.016s 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":285,"lbm_read_time_us":9742,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":466,"lbm_write_time_us":19851,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:26.985414  5349 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:26.985651  5349 tablet_replica.cc:333] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc: stopping tablet replica
I20260812 06:18:26.985776  5349 raft_consensus.cc:2243] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:26.985944  5349 raft_consensus.cc:2272] T 3190f81a92054863993580f822649924 P 030984621eb14673bc3f581d7abebedc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:26.999184  5349 tablet_server.cc:196] TabletServer@127.5.57.65:0 shutdown complete.
I20260812 06:18:27.023856  5349 master.cc:562] Master@127.5.57.126:45311 shutting down...
I20260812 06:18:27.026862  5349 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:27.027019  5349 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:27.027091  5349 tablet_replica.cc:333] T 00000000000000000000000000000000 P 44d600de75444980af18f3c3f32c87d8: stopping tablet replica
I20260812 06:18:27.038877  5349 master.cc:584] Master@127.5.57.126:45311 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5095 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10241 ms total)

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