[==========] 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:16:41.819360  3334 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.65.190:38415
I20260812 06:16:41.820407  3334 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:16:41.821060  3334 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.827888  3345 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:16:41.828092  3334 server_base.cc:1061] running on GCE node
W20260812 06:16:41.828140  3348 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:16:41.827937  3343 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:16:41.828809  3334 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.828902  3334 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:16:41.828930  3334 hybrid_clock.cc:648] HybridClock initialized: now 1786515401828928 us; error 0 us; skew 500 ppm
I20260812 06:16:41.830754  3334 webserver.cc:533] Webserver started at http://127.3.65.190:36487/ using document root <none> and password file <none>
I20260812 06:16:41.831276  3334 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.831336  3334 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.831524  3334 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.833209  3334 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/master-0-root/instance:
uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-x5fp"
I20260812 06:16:41.836530  3334 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:41.838661  3359 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:16:41.839658  3334 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:41.839843  3334 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/master-0-root
uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-x5fp"
I20260812 06:16:41.839956  3334 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-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:16:41.857553  3334 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.858242  3334 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:16:41.858430  3334 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.866302  3437 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.65.190:38415 every 8 connection(s)
I20260812 06:16:41.866307  3334 rpc_server.cc:307] RPC server started. Bound to: 127.3.65.190:38415
I20260812 06:16:41.868513  3439 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:16:41.873840  3439 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: Bootstrap starting.
I20260812 06:16:41.876255  3439 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.877214  3439 log.cc:826] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:41.878885  3439 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: No bootstrap required, opened a new log
I20260812 06:16:41.881598  3439 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER }
I20260812 06:16:41.881758  3439 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.881799  3439 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6bcef5edb0ae44be8ce792af3c8e2d1d, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.882408  3439 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [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: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER }
I20260812 06:16:41.882550  3439 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.882591  3439 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.882680  3439 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.883419  3439 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER }
I20260812 06:16:41.883803  3439 leader_election.cc:304] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [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: 6bcef5edb0ae44be8ce792af3c8e2d1d; no voters: 
I20260812 06:16:41.884083  3439 leader_election.cc:290] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.884275  3446 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.884563  3446 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 1 LEADER]: Becoming Leader. State: Replica: 6bcef5edb0ae44be8ce792af3c8e2d1d, State: Running, Role: LEADER
I20260812 06:16:41.885035  3446 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [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: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER }
I20260812 06:16:41.885124  3439 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:41.887045  3447 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER } }
I20260812 06:16:41.887166  3447 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.887504  3449 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6bcef5edb0ae44be8ce792af3c8e2d1d. Latest consensus state: current_term: 1 leader_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6bcef5edb0ae44be8ce792af3c8e2d1d" member_type: VOTER } }
I20260812 06:16:41.887595  3449 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:41.887622  3334 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:41.889714  3470 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:41.889803  3470 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:41.889907  3469 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:41.890688  3469 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:41.895607  3469 catalog_manager.cc:1383] Generated new cluster ID: aeac344af3554f2c9713f2e1b1e3f458
I20260812 06:16:41.895686  3469 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:41.903893  3469 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:41.904951  3469 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:41.911844  3469 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: Generated new TSK 0
I20260812 06:16:41.912577  3469 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:41.920205  3334 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.923134  3480 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:16:41.923179  3483 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:16:41.923280  3479 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:16:41.923370  3334 server_base.cc:1061] running on GCE node
I20260812 06:16:41.923699  3334 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.923743  3334 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:16:41.923758  3334 hybrid_clock.cc:648] HybridClock initialized: now 1786515401923758 us; error 0 us; skew 500 ppm
I20260812 06:16:41.924778  3334 webserver.cc:533] Webserver started at http://127.3.65.129:33829/ using document root <none> and password file <none>
I20260812 06:16:41.924980  3334 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.925034  3334 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.925136  3334 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.925552  3334 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/instance:
uuid: "0db2a0cdf0c8423687a70880e41e2686"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-x5fp"
I20260812 06:16:41.927094  3334 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:41.928157  3490 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:16:41.928406  3334 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:41.928522  3334 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root
uuid: "0db2a0cdf0c8423687a70880e41e2686"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-x5fp"
I20260812 06:16:41.928617  3334 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-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:16:41.933647  3334 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.934041  3334 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.934528  3334 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:41.935387  3334 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:41.935438  3334 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.935500  3334 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:41.935542  3334 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.942395  3334 rpc_server.cc:307] RPC server started. Bound to: 127.3.65.129:37109
I20260812 06:16:41.942415  3585 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.65.129:37109 every 8 connection(s)
I20260812 06:16:41.952786  3587 heartbeater.cc:344] Connected to a master server at 127.3.65.190:38415
I20260812 06:16:41.953061  3587 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:41.953503  3587 heartbeater.cc:507] Master 127.3.65.190:38415 requested a full tablet report, sending...
I20260812 06:16:41.955084  3384 ts_manager.cc:194] Registered new tserver with Master: 0db2a0cdf0c8423687a70880e41e2686 (127.3.65.129:37109)
I20260812 06:16:41.955397  3334 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012370634s
I20260812 06:16:41.956651  3384 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46774
I20260812 06:16:41.968333  3384 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46780:
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:16:41.984093  3535 tablet_service.cc:1511] Processing CreateTablet for tablet 8e93942f5df64c0283b6dfdf070b4040 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3f2d06b0be614fe9b1ce4b6f12c0bef5]), partition=
I20260812 06:16:41.984570  3535 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8e93942f5df64c0283b6dfdf070b4040. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:41.986919  3613 tablet_bootstrap.cc:492] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Bootstrap starting.
I20260812 06:16:41.988153  3613 tablet_bootstrap.cc:654] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.989423  3613 tablet_bootstrap.cc:492] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: No bootstrap required, opened a new log
I20260812 06:16:41.989522  3613 ts_tablet_manager.cc:1403] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:41.990013  3613 raft_consensus.cc:359] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db2a0cdf0c8423687a70880e41e2686" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 37109 } }
I20260812 06:16:41.990132  3613 raft_consensus.cc:385] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.990166  3613 raft_consensus.cc:740] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0db2a0cdf0c8423687a70880e41e2686, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.990295  3613 consensus_queue.cc:260] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [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: "0db2a0cdf0c8423687a70880e41e2686" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 37109 } }
I20260812 06:16:41.990412  3613 raft_consensus.cc:399] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.990501  3613 raft_consensus.cc:493] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.990559  3613 raft_consensus.cc:3060] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.991497  3613 raft_consensus.cc:515] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db2a0cdf0c8423687a70880e41e2686" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 37109 } }
I20260812 06:16:41.991643  3613 leader_election.cc:304] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [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: 0db2a0cdf0c8423687a70880e41e2686; no voters: 
I20260812 06:16:41.991828  3613 leader_election.cc:290] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.991955  3616 raft_consensus.cc:2804] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.992142  3613 ts_tablet_manager.cc:1434] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:41.992203  3616 raft_consensus.cc:697] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 1 LEADER]: Becoming Leader. State: Replica: 0db2a0cdf0c8423687a70880e41e2686, State: Running, Role: LEADER
I20260812 06:16:41.992386  3587 heartbeater.cc:499] Master 127.3.65.190:38415 was elected leader, sending a full tablet report...
I20260812 06:16:41.992467  3616 consensus_queue.cc:237] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [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: "0db2a0cdf0c8423687a70880e41e2686" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 37109 } }
I20260812 06:16:41.995158  3384 catalog_manager.cc:5719] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0db2a0cdf0c8423687a70880e41e2686 (127.3.65.129). New cstate: current_term: 1 leader_uuid: "0db2a0cdf0c8423687a70880e41e2686" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0db2a0cdf0c8423687a70880e41e2686" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 37109 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.060483  3334 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.014s	sys 0.011s
I20260812 06:16:42.193650  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040): perf score=15.086190
I20260812 06:16:42.355152  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.161s	user 0.108s	sys 0.048s Metrics: {"bytes_written":8615325,"cfile_init":1,"compiler_manager_pool.queue_time_us":437,"delete_count":0,"dirs.queue_time_us":146,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":982,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42445,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":160128,"thread_start_us":105,"threads_started":1,"update_count":1050}
I20260812 06:16:42.356467  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 20743880 bytes of WAL
I20260812 06:16:42.356894  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 2 log segments from log reader
I20260812 06:16:42.356994  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000001 (ops 1-6)
I20260812 06:16:42.357077  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000002 (ops 7-11)
I20260812 06:16:42.362128  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:16:42.362547  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:42.384392  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.022s	user 0.003s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.385013  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:42.507051  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.122s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569858,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":522,"lbm_read_time_us":7529,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20863,"lbm_writes_lt_1ms":343,"mutex_wait_us":57,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":308,"threads_started":5,"update_count":1500}
I20260812 06:16:42.507674  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:42.553277  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.045s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15980,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.553751  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:42.564824  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.565603  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:42.698518  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.133s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":706,"lbm_read_time_us":7737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26640,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:42.699088  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:42.752835  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.054s	user 0.012s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15808,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.753355  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040): 16411393 bytes on disk
I20260812 06:16:42.753857  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.754243  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:42.764789  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.010s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.765206  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:42.905040  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.140s	user 0.089s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1364,"lbm_read_time_us":10397,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22512,"lbm_writes_lt_1ms":443,"mutex_wait_us":370,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:16:42.905656  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:42.955487  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.050s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16512,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.955960  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:42.966821  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.967567  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:43.099442  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.132s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1145,"lbm_read_time_us":9403,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25480,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:16:43.100005  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:43.141837  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.042s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15346,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.142359  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:43.158092  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.158789  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:43.290406  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.131s	user 0.089s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":130,"lbm_read_time_us":9645,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23605,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:16:43.291210  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:43.349061  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.055s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15961,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.349602  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:43.364523  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5516,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.365021  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:43.566497  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.201s	user 0.120s	sys 0.062s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":941,"lbm_read_time_us":12604,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29504,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.567142  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:43.614967  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19854,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.615687  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:43.751839  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.136s	user 0.098s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":182,"lbm_read_time_us":9828,"lbm_reads_lt_1ms":367,"lbm_write_time_us":24823,"lbm_writes_lt_1ms":343,"mutex_wait_us":21,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":1500}
I20260812 06:16:43.752444  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:43.791429  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.039s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.791972  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:43.843149  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.051s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":305,"dirs.run_wall_time_us":1411,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1810,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:43.844163  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 112239314 bytes of WAL
I20260812 06:16:43.844410  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 11 log segments from log reader
I20260812 06:16:43.844461  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000003 (ops 12-16)
I20260812 06:16:43.844522  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000004 (ops 17-20)
I20260812 06:16:43.844578  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000005 (ops 21-25)
I20260812 06:16:43.844641  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000006 (ops 26-30)
I20260812 06:16:43.844712  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000007 (ops 31-35)
I20260812 06:16:43.844785  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000008 (ops 36-40)
I20260812 06:16:43.844838  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000009 (ops 41-45)
I20260812 06:16:43.844885  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000010 (ops 46-50)
I20260812 06:16:43.844930  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000011 (ops 51-55)
I20260812 06:16:43.844978  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000012 (ops 56-60)
I20260812 06:16:43.845023  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000013 (ops 61-65)
I20260812 06:16:43.871423  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.027s	user 0.002s	sys 0.022s Metrics: {}
I20260812 06:16:43.871879  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040): 473 bytes on disk
I20260812 06:16:43.872308  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.872860  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=7.149875
I20260812 06:16:43.897471  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10379,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.898092  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 8767123 bytes of WAL
I20260812 06:16:43.898366  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 1 log segments from log reader
I20260812 06:16:43.898432  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000014 (ops 66-70)
I20260812 06:16:43.900295  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:43.900650  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:43.917490  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.017s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5546,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.917995  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:44.089040  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.171s	user 0.144s	sys 0.026s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1175,"lbm_read_time_us":11843,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35635,"lbm_writes_lt_1ms":643,"mutex_wait_us":813,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:16:44.089826  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:44.145013  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.055s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26242,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.145562  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:44.162940  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.163415  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:44.322194  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.159s	user 0.109s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":9144,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32129,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:44.322872  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:44.387923  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.065s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23569,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.388397  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:44.399538  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.400229  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:44.574767  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.174s	user 0.110s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":11552,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31715,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":59008,"update_count":2500}
I20260812 06:16:44.575361  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:44.635164  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.060s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409865,"delete_count":0,"lbm_write_time_us":17976,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.635710  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:44.646494  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.647047  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:44.837257  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.190s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":13525,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33026,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:16:44.837986  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:44.903704  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.065s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21970,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.904274  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:44.915345  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.915922  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:45.089195  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.173s	user 0.103s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":461,"lbm_read_time_us":12896,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31101,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.090601  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=11.118625
I20260812 06:16:45.155650  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.065s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":34775,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:45.156144  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:45.176376  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.020s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.176951  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:45.186887  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.187345  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:45.347358  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.160s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":483,"lbm_read_time_us":11939,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27697,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.347949  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=10.126437
I20260812 06:16:45.391804  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.044s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18330,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.392319  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:45.407289  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.407923  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:45.441962  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1203,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1863,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:45.442746  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 124257193 bytes of WAL
I20260812 06:16:45.443015  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 12 log segments from log reader
I20260812 06:16:45.443077  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000015 (ops 71-74)
I20260812 06:16:45.443117  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000016 (ops 75-79)
I20260812 06:16:45.443156  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000017 (ops 80-84)
I20260812 06:16:45.443179  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000018 (ops 85-89)
I20260812 06:16:45.443216  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000019 (ops 90-94)
I20260812 06:16:45.443248  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000020 (ops 95-99)
I20260812 06:16:45.443282  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000021 (ops 100-104)
I20260812 06:16:45.443315  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000022 (ops 105-109)
I20260812 06:16:45.443344  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000023 (ops 110-114)
I20260812 06:16:45.443372  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000024 (ops 115-119)
I20260812 06:16:45.443401  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000025 (ops 120-124)
I20260812 06:16:45.443434  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000026 (ops 125-129)
I20260812 06:16:45.473479  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:45.473943  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=3.181125
I20260812 06:16:45.501842  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.028s	user 0.017s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":8182,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.502401  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 12018006 bytes of WAL
I20260812 06:16:45.502646  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 1 log segments from log reader
I20260812 06:16:45.502720  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000027 (ops 130-134)
I20260812 06:16:45.506126  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:45.506517  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:45.523177  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6147,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.523844  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:45.722345  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.198s	user 0.128s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":169,"lbm_read_time_us":15720,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33332,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:16:45.723129  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:45.787964  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.064s	user 0.012s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18249,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.788527  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040): 482 bytes on disk
I20260812 06:16:45.789086  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.789624  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:45.806499  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.807058  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:45.998454  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.191s	user 0.138s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":14596,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33246,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:16:45.999116  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=11.118625
I20260812 06:16:46.033950  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.035s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14403,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.034543  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.067665  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.033s	user 0.011s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5951,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.068159  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.078768  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.079200  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:46.268987  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.190s	user 0.113s	sys 0.065s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":738,"lbm_read_time_us":13002,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30291,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:46.269482  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:46.324676  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.055s	user 0.041s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22272,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.325218  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.336930  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.337420  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:46.537739  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.200s	user 0.151s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":12348,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32389,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:16:46.538465  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=14.095187
I20260812 06:16:46.590287  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.052s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21174,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.590902  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.602917  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.603554  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:46.759794  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.156s	user 0.124s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":709,"lbm_read_time_us":11742,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30412,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2500}
I20260812 06:16:46.760303  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=11.118625
I20260812 06:16:46.802861  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.042s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19637,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.803393  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.826277  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.023s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5626,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.826843  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=2.188937
I20260812 06:16:46.838191  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.838641  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:47.008966  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.170s	user 0.129s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3630,"lbm_read_time_us":10810,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32087,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":3317,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:47.010195  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=12.110812
I20260812 06:16:47.074368  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.064s	user 0.029s	sys 0.023s Metrics: {"bytes_written":13743340,"delete_count":0,"lbm_write_time_us":25696,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1675}
I20260812 06:16:47.074882  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=5.165500
I20260812 06:16:47.094090  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":6769241,"delete_count":0,"lbm_write_time_us":7476,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:16:47.094587  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:47.121963  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushMRSOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1499,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1677,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:47.122624  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling LogGCOp(8e93942f5df64c0283b6dfdf070b4040): free 124710562 bytes of WAL
I20260812 06:16:47.122864  3497 log_reader.cc:385] T 8e93942f5df64c0283b6dfdf070b4040: removed 12 log segments from log reader
I20260812 06:16:47.122910  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000028 (ops 135-139)
I20260812 06:16:47.122941  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000029 (ops 140-144)
I20260812 06:16:47.122985  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000030 (ops 145-149)
I20260812 06:16:47.123034  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000031 (ops 150-154)
I20260812 06:16:47.123054  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000032 (ops 155-159)
I20260812 06:16:47.123108  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000033 (ops 160-164)
I20260812 06:16:47.123162  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000034 (ops 165-169)
I20260812 06:16:47.123200  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000035 (ops 170-174)
I20260812 06:16:47.123255  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000036 (ops 175-179)
I20260812 06:16:47.123303  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000037 (ops 180-184)
I20260812 06:16:47.123345  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000038 (ops 185-189)
I20260812 06:16:47.123390  3497 log.cc:1079] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/8e93942f5df64c0283b6dfdf070b4040/wal-000000039 (ops 190-194)
I20260812 06:16:47.150555  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: LogGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:47.151038  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040): 491 bytes on disk
I20260812 06:16:47.151479  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: UndoDeltaBlockGCOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.152015  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040): perf score=6.157687
I20260812 06:16:47.182569  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: FlushDeltaMemStoresOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.030s	user 0.017s	sys 0.011s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":9388,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.183143  3592 maintenance_manager.cc:419] P 0db2a0cdf0c8423687a70880e41e2686: Scheduling MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040): perf score=1.000000
I20260812 06:16:47.196496  3334 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.136s	user 1.902s	sys 0.152s
I20260812 06:16:47.307920  3334 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.001s	sys 0.000s
I20260812 06:16:47.308581  3334 tablet_server.cc:179] TabletServer@127.3.65.129:0 shutting down...
I20260812 06:16:47.380261  3497 maintenance_manager.cc:643] P 0db2a0cdf0c8423687a70880e41e2686: MajorDeltaCompactionOp(8e93942f5df64c0283b6dfdf070b4040) complete. Timing: real 0.197s	user 0.124s	sys 0.072s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979648,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":475,"lbm_read_time_us":15503,"lbm_reads_lt_1ms":761,"lbm_write_time_us":34134,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":29312,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:16:47.381644  3334 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.382220  3334 tablet_replica.cc:333] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686: stopping tablet replica
I20260812 06:16:47.382491  3334 raft_consensus.cc:2243] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.382738  3334 raft_consensus.cc:2272] T 8e93942f5df64c0283b6dfdf070b4040 P 0db2a0cdf0c8423687a70880e41e2686 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.400224  3334 tablet_server.cc:196] TabletServer@127.3.65.129:0 shutdown complete.
I20260812 06:16:47.440279  3334 master.cc:562] Master@127.3.65.190:38415 shutting down...
I20260812 06:16:47.444254  3334 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.444466  3334 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.444566  3334 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6bcef5edb0ae44be8ce792af3c8e2d1d: stopping tablet replica
I20260812 06:16:47.457381  3334 master.cc:584] Master@127.3.65.190:38415 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5727 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:47.559600  3334 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.65.190:43281
I20260812 06:16:47.560045  3334 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:47.562661  3334 server_base.cc:1061] running on GCE node
W20260812 06:16:47.562736  3648 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:16:47.562801  3652 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:16:47.562822  3649 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:16:47.563215  3334 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.563269  3334 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:16:47.563287  3334 hybrid_clock.cc:648] HybridClock initialized: now 1786515407563286 us; error 0 us; skew 500 ppm
I20260812 06:16:47.564097  3334 webserver.cc:533] Webserver started at http://127.3.65.190:33349/ using document root <none> and password file <none>
I20260812 06:16:47.564231  3334 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.564288  3334 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.564352  3334 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.564702  3334 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/master-0-root/instance:
uuid: "cbc092cef92e46828b7c6558f3cc2abb"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-x5fp"
I20260812 06:16:47.566298  3334 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:47.567205  3657 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:16:47.567513  3334 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:47.567589  3334 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/master-0-root
uuid: "cbc092cef92e46828b7c6558f3cc2abb"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-x5fp"
I20260812 06:16:47.567648  3334 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-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:16:47.572870  3334 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.573151  3334 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.577121  3334 rpc_server.cc:307] RPC server started. Bound to: 127.3.65.190:43281
I20260812 06:16:47.584064  3740 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.65.190:43281 every 8 connection(s)
I20260812 06:16:47.584547  3741 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:16:47.586704  3741 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb: Bootstrap starting.
I20260812 06:16:47.587530  3741 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.588583  3741 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb: No bootstrap required, opened a new log
I20260812 06:16:47.589069  3741 raft_consensus.cc:359] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER }
I20260812 06:16:47.589157  3741 raft_consensus.cc:385] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.589202  3741 raft_consensus.cc:740] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cbc092cef92e46828b7c6558f3cc2abb, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.589391  3741 consensus_queue.cc:260] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [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: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER }
I20260812 06:16:47.589491  3741 raft_consensus.cc:399] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.589519  3741 raft_consensus.cc:493] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.589586  3741 raft_consensus.cc:3060] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.590265  3741 raft_consensus.cc:515] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER }
I20260812 06:16:47.590407  3741 leader_election.cc:304] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [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: cbc092cef92e46828b7c6558f3cc2abb; no voters: 
I20260812 06:16:47.590644  3741 leader_election.cc:290] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.590785  3745 raft_consensus.cc:2804] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.591032  3745 raft_consensus.cc:697] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 1 LEADER]: Becoming Leader. State: Replica: cbc092cef92e46828b7c6558f3cc2abb, State: Running, Role: LEADER
I20260812 06:16:47.591090  3741 sys_catalog.cc:565] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:47.591193  3745 consensus_queue.cc:237] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [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: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER }
I20260812 06:16:47.591645  3752 sys_catalog.cc:455] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [sys.catalog]: SysCatalogTable state changed. Reason: New leader cbc092cef92e46828b7c6558f3cc2abb. Latest consensus state: current_term: 1 leader_uuid: "cbc092cef92e46828b7c6558f3cc2abb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER } }
I20260812 06:16:47.591745  3752 sys_catalog.cc:458] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.591631  3751 sys_catalog.cc:455] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "cbc092cef92e46828b7c6558f3cc2abb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cbc092cef92e46828b7c6558f3cc2abb" member_type: VOTER } }
I20260812 06:16:47.591810  3751 sys_catalog.cc:458] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.592356  3762 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:47.593319  3762 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:47.593544  3334 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:47.595078  3762 catalog_manager.cc:1383] Generated new cluster ID: 3ea5a8b9f8ed4549ba2a62ce5ed8e36e
I20260812 06:16:47.595137  3762 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:47.605607  3762 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:47.606142  3762 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:47.616076  3762 catalog_manager.cc:6092] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb: Generated new TSK 0
I20260812 06:16:47.616254  3762 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:47.625818  3334 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:47.628253  3790 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:16:47.628312  3788 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:16:47.628404  3795 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:16:47.628491  3334 server_base.cc:1061] running on GCE node
I20260812 06:16:47.628638  3334 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.628674  3334 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:16:47.628696  3334 hybrid_clock.cc:648] HybridClock initialized: now 1786515407628696 us; error 0 us; skew 500 ppm
I20260812 06:16:47.629596  3334 webserver.cc:533] Webserver started at http://127.3.65.129:39033/ using document root <none> and password file <none>
I20260812 06:16:47.629734  3334 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.629781  3334 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.629832  3334 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.630198  3334 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/instance:
uuid: "befec219d5fd415a8f36dc454189df77"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-x5fp"
I20260812 06:16:47.631639  3334 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:47.632511  3803 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:16:47.632808  3334 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:47.632882  3334 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root
uuid: "befec219d5fd415a8f36dc454189df77"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-x5fp"
I20260812 06:16:47.632980  3334 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-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:16:47.637984  3334 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.638345  3334 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.638643  3334 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:47.639110  3334 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:47.639173  3334 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.639233  3334 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:47.639266  3334 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.643741  3334 rpc_server.cc:307] RPC server started. Bound to: 127.3.65.129:35069
I20260812 06:16:47.644335  3904 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.65.129:35069 every 8 connection(s)
I20260812 06:16:47.649627  3906 heartbeater.cc:344] Connected to a master server at 127.3.65.190:43281
I20260812 06:16:47.649755  3906 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:47.650029  3906 heartbeater.cc:507] Master 127.3.65.190:43281 requested a full tablet report, sending...
I20260812 06:16:47.650739  3679 ts_manager.cc:194] Registered new tserver with Master: befec219d5fd415a8f36dc454189df77 (127.3.65.129:35069)
I20260812 06:16:47.651335  3334 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0066651s
I20260812 06:16:47.651598  3679 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57440
I20260812 06:16:47.659456  3679 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57446:
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:16:47.670415  3844 tablet_service.cc:1511] Processing CreateTablet for tablet 2e488d0781a04184830267647671e780 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a4a96054a2b64cdc90bb1b71ceed1bfc]), partition=
I20260812 06:16:47.670758  3844 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2e488d0781a04184830267647671e780. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:47.672983  3919 tablet_bootstrap.cc:492] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Bootstrap starting.
I20260812 06:16:47.673959  3919 tablet_bootstrap.cc:654] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.675246  3919 tablet_bootstrap.cc:492] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: No bootstrap required, opened a new log
I20260812 06:16:47.675375  3919 ts_tablet_manager.cc:1403] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:47.675797  3919 raft_consensus.cc:359] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "befec219d5fd415a8f36dc454189df77" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 35069 } }
I20260812 06:16:47.675926  3919 raft_consensus.cc:385] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.675990  3919 raft_consensus.cc:740] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: befec219d5fd415a8f36dc454189df77, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.676160  3919 consensus_queue.cc:260] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [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: "befec219d5fd415a8f36dc454189df77" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 35069 } }
I20260812 06:16:47.676262  3919 raft_consensus.cc:399] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.676308  3919 raft_consensus.cc:493] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.676360  3919 raft_consensus.cc:3060] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.677286  3919 raft_consensus.cc:515] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "befec219d5fd415a8f36dc454189df77" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 35069 } }
I20260812 06:16:47.677459  3919 leader_election.cc:304] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [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: befec219d5fd415a8f36dc454189df77; no voters: 
I20260812 06:16:47.677690  3919 leader_election.cc:290] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.677872  3922 raft_consensus.cc:2804] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.678028  3919 ts_tablet_manager.cc:1434] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:47.678077  3906 heartbeater.cc:499] Master 127.3.65.190:43281 was elected leader, sending a full tablet report...
I20260812 06:16:47.678148  3922 raft_consensus.cc:697] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 1 LEADER]: Becoming Leader. State: Replica: befec219d5fd415a8f36dc454189df77, State: Running, Role: LEADER
I20260812 06:16:47.678333  3922 consensus_queue.cc:237] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [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: "befec219d5fd415a8f36dc454189df77" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 35069 } }
I20260812 06:16:47.679883  3679 catalog_manager.cc:5719] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 reported cstate change: term changed from 0 to 1, leader changed from <none> to befec219d5fd415a8f36dc454189df77 (127.3.65.129). New cstate: current_term: 1 leader_uuid: "befec219d5fd415a8f36dc454189df77" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "befec219d5fd415a8f36dc454189df77" member_type: VOTER last_known_addr { host: "127.3.65.129" port: 35069 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:47.738617  3334 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.009s
I20260812 06:16:47.895105  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushMRSOp(2e488d0781a04184830267647671e780): perf score=19.054940
I20260812 06:16:48.062990  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushMRSOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.168s	user 0.134s	sys 0.032s Metrics: {"bytes_written":12758747,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":893,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42876,"lbm_writes_lt_1ms":778,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":9472,"update_count":1555}
I20260812 06:16:48.063791  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling LogGCOp(2e488d0781a04184830267647671e780): free 20743880 bytes of WAL
I20260812 06:16:48.064116  3810 log_reader.cc:385] T 2e488d0781a04184830267647671e780: removed 2 log segments from log reader
I20260812 06:16:48.064200  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000001 (ops 1-6)
I20260812 06:16:48.064254  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000002 (ops 7-11)
I20260812 06:16:48.068859  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: LogGCOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:48.069177  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling UndoDeltaBlockGCOp(2e488d0781a04184830267647671e780): 16821647 bytes on disk
I20260812 06:16:48.069583  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: UndoDeltaBlockGCOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.070020  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:48.085583  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.015s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3651384,"delete_count":0,"lbm_write_time_us":3588,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:16:48.086068  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:48.101300  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.101876  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling MajorDeltaCompactionOp(2e488d0781a04184830267647671e780): perf score=1.000000
I20260812 06:16:48.310145  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: MajorDeltaCompactionOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.208s	user 0.168s	sys 0.040s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405531,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":821,"lbm_read_time_us":13679,"lbm_reads_lt_1ms":559,"lbm_write_time_us":39569,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":385,"threads_started":5,"update_count":2450}
I20260812 06:16:48.310900  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=14.095187
I20260812 06:16:48.371996  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.061s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26628,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.372473  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:48.396600  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.024s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.397130  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:48.408188  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.408638  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling MajorDeltaCompactionOp(2e488d0781a04184830267647671e780): perf score=1.000000
I20260812 06:16:48.706935  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: MajorDeltaCompactionOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.298s	user 0.136s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918212,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1127,"lbm_read_time_us":15299,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36095,"lbm_writes_lt_1ms":643,"mutex_wait_us":921,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":3000}
I20260812 06:16:48.707819  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=22.032687
I20260812 06:16:48.803937  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.096s	user 0.056s	sys 0.019s Metrics: {"bytes_written":24614721,"delete_count":0,"lbm_write_time_us":34415,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:16:48.804456  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:48.893874  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.089s	user 0.022s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9338,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:48.894678  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:48.991264  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.096s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9588,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:48.991832  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:49.095007  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.103s	user 0.013s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9490,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.095709  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:49.190886  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.095s	user 0.016s	sys 0.011s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12422,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:49.191431  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:49.291481  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.100s	user 0.013s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11419,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.292260  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=10.126437
I20260812 06:16:49.397505  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.105s	user 0.018s	sys 0.016s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":14589,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:49.398080  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:49.503777  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.105s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11795,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.504951  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=10.126437
I20260812 06:16:49.610018  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.105s	user 0.014s	sys 0.024s Metrics: {"bytes_written":11774178,"delete_count":0,"lbm_write_time_us":17334,"lbm_writes_lt_1ms":290,"reinsert_count":0,"update_count":1435}
I20260812 06:16:49.610669  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:49.712878  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.102s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8328154,"delete_count":0,"lbm_write_time_us":8955,"lbm_writes_lt_1ms":206,"mutex_wait_us":187,"reinsert_count":0,"update_count":1015}
I20260812 06:16:49.714001  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:49.815397  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.101s	user 0.014s	sys 0.017s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":13823,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:49.815944  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:49.917479  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.101s	user 0.013s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8589,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.918166  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=9.134250
I20260812 06:16:50.015174  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.097s	user 0.015s	sys 0.016s Metrics: {"bytes_written":11404960,"delete_count":0,"lbm_write_time_us":13577,"lbm_writes_lt_1ms":281,"mutex_wait_us":122,"reinsert_count":0,"update_count":1390}
I20260812 06:16:50.015901  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:50.129240  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.113s	user 0.021s	sys 0.007s Metrics: {"bytes_written":9107611,"delete_count":0,"lbm_write_time_us":12072,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:50.130093  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:50.230237  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.100s	user 0.017s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9955,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:50.230892  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:50.333372  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.102s	user 0.028s	sys 0.000s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":12071,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:50.334035  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=10.126437
I20260812 06:16:50.433323  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.099s	user 0.023s	sys 0.016s Metrics: {"bytes_written":11815201,"delete_count":0,"lbm_write_time_us":17437,"lbm_writes_lt_1ms":291,"reinsert_count":0,"update_count":1440}
I20260812 06:16:50.433970  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:50.531458  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.097s	user 0.015s	sys 0.013s Metrics: {"bytes_written":8287130,"delete_count":0,"lbm_write_time_us":12592,"lbm_writes_lt_1ms":205,"reinsert_count":0,"update_count":1010}
I20260812 06:16:50.532114  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:50.635378  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.103s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10363,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:50.636003  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:50.737093  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.101s	user 0.014s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10539,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:50.737771  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:50.838528  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.101s	user 0.018s	sys 0.010s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":12688,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:50.839277  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=9.134250
I20260812 06:16:50.934789  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.095s	user 0.017s	sys 0.010s Metrics: {"bytes_written":10994719,"delete_count":0,"lbm_write_time_us":12091,"lbm_writes_lt_1ms":271,"reinsert_count":0,"update_count":1340}
I20260812 06:16:50.935568  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:51.036660  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.101s	user 0.007s	sys 0.020s Metrics: {"bytes_written":9107612,"delete_count":0,"lbm_write_time_us":12468,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:51.037691  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=6.157687
I20260812 06:16:51.139914  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.102s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10976,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:51.140888  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:51.162927  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.022s	user 0.019s	sys 0.001s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9282,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:51.163462  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:51.226503  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.063s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5409,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.227100  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=3.181125
I20260812 06:16:51.247501  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.020s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7033,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:51.248039  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:51.258188  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.258749  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushMRSOp(2e488d0781a04184830267647671e780): perf score=1.195565
I20260812 06:16:51.299171  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushMRSOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":2955749,"cfile_init":1,"dirs.queue_time_us":225,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1647,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3649,"lbm_writes_lt_1ms":49,"peak_mem_usage":0,"rows_written":72,"thread_start_us":85,"threads_started":1}
I20260812 06:16:51.299863  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling LogGCOp(2e488d0781a04184830267647671e780): free 299305089 bytes of WAL
I20260812 06:16:51.300144  3810 log_reader.cc:385] T 2e488d0781a04184830267647671e780: removed 30 log segments from log reader
I20260812 06:16:51.300190  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000003 (ops 12-16)
I20260812 06:16:51.300221  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000004 (ops 17-21)
I20260812 06:16:51.300263  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000005 (ops 22-26)
I20260812 06:16:51.300312  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000006 (ops 27-30)
I20260812 06:16:51.300345  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000007 (ops 31-35)
I20260812 06:16:51.300388  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000008 (ops 36-40)
I20260812 06:16:51.300513  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000009 (ops 41-44)
I20260812 06:16:51.300578  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000010 (ops 45-49)
I20260812 06:16:51.300649  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000011 (ops 50-54)
I20260812 06:16:51.300707  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000012 (ops 55-59)
I20260812 06:16:51.300844  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000013 (ops 60-64)
I20260812 06:16:51.300927  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000014 (ops 65-69)
I20260812 06:16:51.300992  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000015 (ops 70-74)
I20260812 06:16:51.301064  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000016 (ops 75-78)
I20260812 06:16:51.301131  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000017 (ops 79-83)
I20260812 06:16:51.301184  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000018 (ops 84-88)
I20260812 06:16:51.301257  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000019 (ops 89-92)
I20260812 06:16:51.301298  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000020 (ops 93-97)
I20260812 06:16:51.301371  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000021 (ops 98-102)
I20260812 06:16:51.301412  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000022 (ops 103-106)
I20260812 06:16:51.301486  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000023 (ops 107-111)
I20260812 06:16:51.301525  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000024 (ops 112-116)
I20260812 06:16:51.301589  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000025 (ops 117-120)
I20260812 06:16:51.301630  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000026 (ops 121-125)
I20260812 06:16:51.301699  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000027 (ops 126-130)
I20260812 06:16:51.301739  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000028 (ops 131-135)
I20260812 06:16:51.301816  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000029 (ops 136-140)
I20260812 06:16:51.301856  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000030 (ops 141-145)
I20260812 06:16:51.301925  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000031 (ops 146-150)
I20260812 06:16:51.301965  3810 log.cc:1079] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: Deleting log segment in path: /tmp/dist-test-taskKfTYdA/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515401808749-3334-0/minicluster-data/ts-0-root/wals/2e488d0781a04184830267647671e780/wal-000000032 (ops 151-155)
I20260812 06:16:51.373050  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: LogGCOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.073s	user 0.000s	sys 0.072s Metrics: {}
I20260812 06:16:51.373499  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=7.149875
I20260812 06:16:51.403192  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.029s	user 0.012s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13005,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:51.403744  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling UndoDeltaBlockGCOp(2e488d0781a04184830267647671e780): 944 bytes on disk
I20260812 06:16:51.404186  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: UndoDeltaBlockGCOp(2e488d0781a04184830267647671e780) 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:16:51.404686  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=2.188937
I20260812 06:16:51.422139  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.017s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.422780  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling MajorDeltaCompactionOp(2e488d0781a04184830267647671e780): perf score=1.000000
I20260812 06:16:52.625195  3334 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.886s	user 1.739s	sys 0.137s
I20260812 06:16:53.219939  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: MajorDeltaCompactionOp(2e488d0781a04184830267647671e780) complete. Timing: real 1.797s	user 1.014s	sys 0.777s Metrics: {"cfile_cache_miss":6560,"cfile_cache_miss_bytes":270963764,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":30,"delta_iterators_relevant":30,"lbm_read_time_us":116448,"lbm_reads_lt_1ms":6588,"lbm_write_time_us":340905,"lbm_writes_lt_1ms":6548,"peak_mem_usage":808710220,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":32500}
I20260812 06:16:53.220573  3907 maintenance_manager.cc:419] P befec219d5fd415a8f36dc454189df77: Scheduling FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780): perf score=77.595187
W20260812 06:16:53.362457  3334 scanner-internal.cc:458] Time spent opening tablet: real 0.737s	user 0.000s	sys 0.000s
I20260812 06:16:53.366683  3334 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.741s	user 0.003s	sys 0.000s
I20260812 06:16:53.367286  3334 tablet_server.cc:179] TabletServer@127.3.65.129:0 shutting down...
I20260812 06:16:53.454273  3810 maintenance_manager.cc:643] P befec219d5fd415a8f36dc454189df77: FlushDeltaMemStoresOp(2e488d0781a04184830267647671e780) complete. Timing: real 0.233s	user 0.117s	sys 0.072s Metrics: {"bytes_written":82048616,"delete_count":0,"lbm_write_time_us":84895,"lbm_writes_lt_1ms":2005,"reinsert_count":0,"update_count":10000}
I20260812 06:16:53.454981  3334 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:53.455235  3334 tablet_replica.cc:333] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77: stopping tablet replica
I20260812 06:16:53.455446  3334 raft_consensus.cc:2243] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:53.455639  3334 raft_consensus.cc:2272] T 2e488d0781a04184830267647671e780 P befec219d5fd415a8f36dc454189df77 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:53.469365  3334 tablet_server.cc:196] TabletServer@127.3.65.129:0 shutdown complete.
I20260812 06:16:54.386641  3334 master.cc:562] Master@127.3.65.190:43281 shutting down...
I20260812 06:16:54.390394  3334 raft_consensus.cc:2243] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.390621  3334 raft_consensus.cc:2272] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.390717  3334 tablet_replica.cc:333] T 00000000000000000000000000000000 P cbc092cef92e46828b7c6558f3cc2abb: stopping tablet replica
I20260812 06:16:54.403704  3334 master.cc:584] Master@127.3.65.190:43281 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6970 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12699 ms total)

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