[==========] 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:20:15.221513 23759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.51.254:39321
I20260812 06:20:15.222618 23759 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:20:15.223241 23759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:15.229980 23759 server_base.cc:1061] running on GCE node
W20260812 06:20:15.229935 23770 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:20:15.230149 23773 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:20:15.230162 23769 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:20:15.230746 23759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.230841 23759 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:20:15.230878 23759 hybrid_clock.cc:648] HybridClock initialized: now 1786515615230876 us; error 0 us; skew 500 ppm
I20260812 06:20:15.232851 23759 webserver.cc:533] Webserver started at http://127.23.51.254:40605/ using document root <none> and password file <none>
I20260812 06:20:15.233471 23759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.233536 23759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.233801 23759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.235517 23759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/master-0-root/instance:
uuid: "af1c9f1df31f4d84b5aa0b74690ced35"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-rmhg"
I20260812 06:20:15.239320 23759 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:15.241689 23782 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:20:15.242847 23759 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:15.242966 23759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/master-0-root
uuid: "af1c9f1df31f4d84b5aa0b74690ced35"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-rmhg"
I20260812 06:20:15.243081 23759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-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:20:15.256861 23759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.257622 23759 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:20:15.257793 23759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.265337 23759 rpc_server.cc:307] RPC server started. Bound to: 127.23.51.254:39321
I20260812 06:20:15.265357 23868 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.51.254:39321 every 8 connection(s)
I20260812 06:20:15.267671 23869 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:20:15.273258 23869 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: Bootstrap starting.
I20260812 06:20:15.275628 23869 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.276547 23869 log.cc:826] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:15.278344 23869 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: No bootstrap required, opened a new log
I20260812 06:20:15.281193 23869 raft_consensus.cc:359] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER }
I20260812 06:20:15.281381 23869 raft_consensus.cc:385] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.281451 23869 raft_consensus.cc:740] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af1c9f1df31f4d84b5aa0b74690ced35, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.282060 23869 consensus_queue.cc:260] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [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: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER }
I20260812 06:20:15.282209 23869 raft_consensus.cc:399] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.282281 23869 raft_consensus.cc:493] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.282407 23869 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.283218 23869 raft_consensus.cc:515] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER }
I20260812 06:20:15.283679 23869 leader_election.cc:304] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [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: af1c9f1df31f4d84b5aa0b74690ced35; no voters: 
I20260812 06:20:15.284024 23869 leader_election.cc:290] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.284154 23875 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.284374 23875 raft_consensus.cc:697] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 1 LEADER]: Becoming Leader. State: Replica: af1c9f1df31f4d84b5aa0b74690ced35, State: Running, Role: LEADER
I20260812 06:20:15.284778 23875 consensus_queue.cc:237] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [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: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER }
I20260812 06:20:15.285053 23869 sys_catalog.cc:565] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:15.286700 23877 sys_catalog.cc:455] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [sys.catalog]: SysCatalogTable state changed. Reason: New leader af1c9f1df31f4d84b5aa0b74690ced35. Latest consensus state: current_term: 1 leader_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER } }
I20260812 06:20:15.286732 23876 sys_catalog.cc:455] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af1c9f1df31f4d84b5aa0b74690ced35" member_type: VOTER } }
I20260812 06:20:15.286844 23876 sys_catalog.cc:458] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.286844 23877 sys_catalog.cc:458] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.287214 23896 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:15.287243 23759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:15.289847 23896 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:15.295059 23896 catalog_manager.cc:1383] Generated new cluster ID: dd914a99a2c64e4fbea5260f83415331
I20260812 06:20:15.295210 23896 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:15.303419 23896 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:15.304301 23896 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:15.311784 23896 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: Generated new TSK 0
I20260812 06:20:15.312482 23896 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:15.320256 23759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:15.322997 23911 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:20:15.323052 23906 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:20:15.323117 23909 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:20:15.323310 23759 server_base.cc:1061] running on GCE node
I20260812 06:20:15.323451 23759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.323488 23759 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:20:15.323508 23759 hybrid_clock.cc:648] HybridClock initialized: now 1786515615323508 us; error 0 us; skew 500 ppm
I20260812 06:20:15.324463 23759 webserver.cc:533] Webserver started at http://127.23.51.193:33599/ using document root <none> and password file <none>
I20260812 06:20:15.324652 23759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.324712 23759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.324793 23759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.325248 23759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/instance:
uuid: "a6143224c80744518627e2633912fca5"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-rmhg"
I20260812 06:20:15.326689 23759 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:15.327670 23922 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:20:15.327925 23759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:15.327998 23759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root
uuid: "a6143224c80744518627e2633912fca5"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-rmhg"
I20260812 06:20:15.328083 23759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-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:20:15.346747 23759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.347265 23759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.347755 23759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:15.348706 23759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:15.348763 23759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.348825 23759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:15.348848 23759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.355235 23759 rpc_server.cc:307] RPC server started. Bound to: 127.23.51.193:36075
I20260812 06:20:15.355262 24041 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.51.193:36075 every 8 connection(s)
I20260812 06:20:15.369439 24045 heartbeater.cc:344] Connected to a master server at 127.23.51.254:39321
I20260812 06:20:15.369729 24045 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:15.370312 24045 heartbeater.cc:507] Master 127.23.51.254:39321 requested a full tablet report, sending...
I20260812 06:20:15.371784 23811 ts_manager.cc:194] Registered new tserver with Master: a6143224c80744518627e2633912fca5 (127.23.51.193:36075)
I20260812 06:20:15.372541 23759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016676304s
I20260812 06:20:15.372953 23811 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40676
I20260812 06:20:15.382627 23811 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40692:
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:20:15.397490 23966 tablet_service.cc:1511] Processing CreateTablet for tablet 484e6dcb006448eba0b33371392e1851 (DEFAULT_TABLE table=heavy-update-compaction-test [id=75af13fd6c994be89d487cd7d3d44c19]), partition=
I20260812 06:20:15.397986 23966 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 484e6dcb006448eba0b33371392e1851. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:15.400233 24065 tablet_bootstrap.cc:492] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Bootstrap starting.
I20260812 06:20:15.401206 24065 tablet_bootstrap.cc:654] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.402612 24065 tablet_bootstrap.cc:492] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: No bootstrap required, opened a new log
I20260812 06:20:15.402732 24065 ts_tablet_manager.cc:1403] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:15.403260 24065 raft_consensus.cc:359] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6143224c80744518627e2633912fca5" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 36075 } }
I20260812 06:20:15.403393 24065 raft_consensus.cc:385] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.403434 24065 raft_consensus.cc:740] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a6143224c80744518627e2633912fca5, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.403579 24065 consensus_queue.cc:260] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [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: "a6143224c80744518627e2633912fca5" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 36075 } }
I20260812 06:20:15.403676 24065 raft_consensus.cc:399] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.403712 24065 raft_consensus.cc:493] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.403750 24065 raft_consensus.cc:3060] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.404810 24065 raft_consensus.cc:515] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6143224c80744518627e2633912fca5" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 36075 } }
I20260812 06:20:15.405011 24065 leader_election.cc:304] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [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: a6143224c80744518627e2633912fca5; no voters: 
I20260812 06:20:15.405300 24065 leader_election.cc:290] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.405416 24067 raft_consensus.cc:2804] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.405650 24065 ts_tablet_manager.cc:1434] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:20:15.405655 24067 raft_consensus.cc:697] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 1 LEADER]: Becoming Leader. State: Replica: a6143224c80744518627e2633912fca5, State: Running, Role: LEADER
I20260812 06:20:15.405875 24045 heartbeater.cc:499] Master 127.23.51.254:39321 was elected leader, sending a full tablet report...
I20260812 06:20:15.405886 24067 consensus_queue.cc:237] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [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: "a6143224c80744518627e2633912fca5" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 36075 } }
I20260812 06:20:15.408560 23811 catalog_manager.cc:5719] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 reported cstate change: term changed from 0 to 1, leader changed from <none> to a6143224c80744518627e2633912fca5 (127.23.51.193). New cstate: current_term: 1 leader_uuid: "a6143224c80744518627e2633912fca5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a6143224c80744518627e2633912fca5" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 36075 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:15.483153 23759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.026s	sys 0.010s
I20260812 06:20:15.606514 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushMRSOp(484e6dcb006448eba0b33371392e1851): perf score=15.086190
I20260812 06:20:15.768931 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushMRSOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.162s	user 0.133s	sys 0.024s Metrics: {"bytes_written":13497181,"cfile_init":1,"compiler_manager_pool.queue_time_us":223,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":838,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39777,"lbm_writes_lt_1ms":696,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":99712,"thread_start_us":126,"threads_started":1,"update_count":1645}
I20260812 06:20:15.770135 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851): 12719213 bytes on disk
I20260812 06:20:15.770855 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:20:15.771266 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=3.181125
I20260812 06:20:15.785427 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":5275,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:20:15.785931 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling LogGCOp(484e6dcb006448eba0b33371392e1851): free 20743880 bytes of WAL
I20260812 06:20:15.786244 23932 log_reader.cc:385] T 484e6dcb006448eba0b33371392e1851: removed 2 log segments from log reader
I20260812 06:20:15.786358 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000001 (ops 1-6)
I20260812 06:20:15.786446 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000002 (ops 7-11)
I20260812 06:20:15.791437 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: LogGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:15.791887 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=1.196750
I20260812 06:20:15.805792 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":2256529,"delete_count":0,"lbm_write_time_us":3268,"lbm_writes_lt_1ms":58,"reinsert_count":0,"update_count":275}
I20260812 06:20:15.806481 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:15.975395 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.169s	user 0.131s	sys 0.036s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364517,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":480,"lbm_read_time_us":13012,"lbm_reads_lt_1ms":551,"lbm_write_time_us":26560,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":273,"threads_started":5,"update_count":2450}
I20260812 06:20:15.975979 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=11.118625
I20260812 06:20:16.007829 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.032s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":13290,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:16.008308 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.031009 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.023s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3848,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.031579 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.041795 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.042248 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.194026 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.152s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774804,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1155,"lbm_read_time_us":9574,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29980,"lbm_writes_lt_1ms":543,"mutex_wait_us":545,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:20:16.194687 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:16.230167 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.035s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13473,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.230844 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.248835 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6379,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.249461 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.372377 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.123s	user 0.093s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":7300,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24229,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.372920 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:16.408938 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.036s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13146,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.409602 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.420944 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.421530 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.542838 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.121s	user 0.087s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1040,"lbm_read_time_us":9121,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22039,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:20:16.543330 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:16.592373 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.049s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14791,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.593067 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.608680 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.609283 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.748279 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.139s	user 0.074s	sys 0.061s 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":197,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20274,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:20:16.748860 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:16.784291 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.035s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12380,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.784864 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.887393 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.102s	user 0.085s	sys 0.017s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":377,"lbm_read_time_us":5929,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18247,"lbm_writes_lt_1ms":343,"mutex_wait_us":39,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:20:16.888032 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:16.924952 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.037s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.925592 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:16.936187 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.936844 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushMRSOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:16.970062 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushMRSOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.033s	user 0.026s	sys 0.006s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":220,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1986,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:16.970890 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling LogGCOp(484e6dcb006448eba0b33371392e1851): free 112692397 bytes of WAL
I20260812 06:20:16.971170 23932 log_reader.cc:385] T 484e6dcb006448eba0b33371392e1851: removed 11 log segments from log reader
I20260812 06:20:16.971220 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000003 (ops 12-16)
I20260812 06:20:16.971247 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000004 (ops 17-21)
I20260812 06:20:16.971275 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000005 (ops 22-26)
I20260812 06:20:16.971306 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000006 (ops 27-31)
I20260812 06:20:16.971338 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000007 (ops 32-36)
I20260812 06:20:16.971369 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000008 (ops 37-41)
I20260812 06:20:16.971386 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000009 (ops 42-46)
I20260812 06:20:16.971417 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000010 (ops 47-51)
I20260812 06:20:16.971449 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000011 (ops 52-56)
I20260812 06:20:16.971663 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000012 (ops 57-61)
I20260812 06:20:16.971707 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000013 (ops 62-66)
I20260812 06:20:16.994560 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: LogGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:16.994969 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851): 449 bytes on disk
I20260812 06:20:16.995467 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.996059 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=3.181125
I20260812 06:20:17.010149 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:17.010596 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:17.020323 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.010s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3293,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.020913 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:17.201887 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.181s	user 0.124s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2668,"lbm_read_time_us":11017,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31983,"lbm_writes_lt_1ms":643,"mutex_wait_us":332,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:20:17.202513 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:17.252466 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23011,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.253088 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:17.269781 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.270241 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:17.411145 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.141s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":8791,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25245,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:17.411757 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:17.462307 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.050s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19582,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.462903 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:17.478852 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.479391 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:17.649669 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.170s	user 0.118s	sys 0.047s 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":981,"lbm_read_time_us":11594,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28367,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:20:17.650244 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:17.711364 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.061s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20987,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.711938 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:17.723102 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.723853 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:17.893977 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.170s	user 0.099s	sys 0.064s 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":580,"lbm_read_time_us":12280,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27940,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:17.894531 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:17.944527 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.050s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18178,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.945258 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:17.961836 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.962366 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:18.129400 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.167s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":11680,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27396,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:20:18.129956 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:18.186239 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.056s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.186975 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:18.198057 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.198561 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:18.358915 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.160s	user 0.098s	sys 0.062s 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":400,"lbm_read_time_us":12710,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26379,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:18.359797 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=11.118625
I20260812 06:20:18.393759 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.034s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":14822,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.394523 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:18.411180 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5411,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:20:18.411662 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushMRSOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:18.461387 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushMRSOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.050s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1901,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:18.462146 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851): 493 bytes on disk
I20260812 06:20:18.462680 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.463303 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=3.181125
I20260812 06:20:18.477567 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:18.478029 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling LogGCOp(484e6dcb006448eba0b33371392e1851): free 132571311 bytes of WAL
I20260812 06:20:18.478258 23932 log_reader.cc:385] T 484e6dcb006448eba0b33371392e1851: removed 13 log segments from log reader
I20260812 06:20:18.478304 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000014 (ops 67-71)
I20260812 06:20:18.478334 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000015 (ops 72-76)
I20260812 06:20:18.478364 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000016 (ops 77-80)
I20260812 06:20:18.478395 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000017 (ops 81-85)
I20260812 06:20:18.478428 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000018 (ops 86-90)
I20260812 06:20:18.478461 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000019 (ops 91-95)
I20260812 06:20:18.478494 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000020 (ops 96-100)
I20260812 06:20:18.478526 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000021 (ops 101-104)
I20260812 06:20:18.478564 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000022 (ops 105-109)
I20260812 06:20:18.478597 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000023 (ops 110-114)
I20260812 06:20:18.478628 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000024 (ops 115-119)
I20260812 06:20:18.478660 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000025 (ops 120-124)
I20260812 06:20:18.478693 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000026 (ops 125-129)
I20260812 06:20:18.501590 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: LogGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:18.502140 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:18.521638 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.019s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5348,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.522110 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:18.532738 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.533336 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:18.748617 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.215s	user 0.138s	sys 0.073s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":3701,"lbm_read_time_us":14149,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38336,"lbm_writes_lt_1ms":743,"mutex_wait_us":2579,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:20:18.749130 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=15.087375
I20260812 06:20:18.787192 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.038s	user 0.027s	sys 0.009s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":16425,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:18.787774 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:18.807524 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5497,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.808014 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:18.972085 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.164s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1252,"lbm_read_time_us":11342,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27531,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:20:18.972803 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:19.021296 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.048s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20746,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.021836 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:19.037763 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.038380 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:19.217087 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.178s	user 0.115s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":637,"lbm_read_time_us":12198,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27267,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:20:19.217861 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:19.269102 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.051s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18317,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.269659 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:19.280650 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.281136 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:19.445677 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.164s	user 0.124s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":12059,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27302,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:19.446394 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:19.485929 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.039s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15836,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.486927 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:19.510620 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.511157 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:19.529920 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.530427 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:19.697460 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.167s	user 0.103s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":344,"lbm_read_time_us":12231,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28241,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:19.698418 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=11.118625
I20260812 06:20:19.732784 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14425,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:19.733614 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:19.749413 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5138,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.749948 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:19.872247 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.122s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":9133,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24611,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:20:19.872864 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=10.126437
I20260812 06:20:19.918820 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.046s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13885,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.919422 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushMRSOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:19.957086 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushMRSOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.037s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":297,"dirs.run_wall_time_us":1354,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1534,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:19.958045 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851): 472 bytes on disk
I20260812 06:20:19.958587 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: UndoDeltaBlockGCOp(484e6dcb006448eba0b33371392e1851) 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:20:19.959260 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=3.181125
I20260812 06:20:19.971000 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:19.971604 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling LogGCOp(484e6dcb006448eba0b33371392e1851): free 124710562 bytes of WAL
I20260812 06:20:19.971839 23932 log_reader.cc:385] T 484e6dcb006448eba0b33371392e1851: removed 12 log segments from log reader
I20260812 06:20:19.971887 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000027 (ops 130-134)
I20260812 06:20:19.971916 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000028 (ops 135-139)
I20260812 06:20:19.971942 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000029 (ops 140-144)
I20260812 06:20:19.971974 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000030 (ops 145-149)
I20260812 06:20:19.972007 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000031 (ops 150-154)
I20260812 06:20:19.972039 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000032 (ops 155-159)
I20260812 06:20:19.972070 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000033 (ops 160-164)
I20260812 06:20:19.972110 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000034 (ops 165-169)
I20260812 06:20:19.972142 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000035 (ops 170-174)
I20260812 06:20:19.972173 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000036 (ops 175-179)
I20260812 06:20:19.972205 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000037 (ops 180-184)
I20260812 06:20:19.972235 23932 log.cc:1079] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/484e6dcb006448eba0b33371392e1851/wal-000000038 (ops 185-189)
I20260812 06:20:19.998215 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: LogGCOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:19.998709 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:20.018069 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.019s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3795,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.018638 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=2.188937
I20260812 06:20:20.029482 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.030031 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851): perf score=1.000000
I20260812 06:20:20.210754 23759 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.728s	user 1.709s	sys 0.112s
I20260812 06:20:20.215214 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: MajorDeltaCompactionOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.185s	user 0.151s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2795,"lbm_read_time_us":13511,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33370,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:20:20.215736 24048 maintenance_manager.cc:419] P a6143224c80744518627e2633912fca5: Scheduling FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851): perf score=14.095187
I20260812 06:20:20.242918 23759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.032s	user 0.002s	sys 0.000s
I20260812 06:20:20.243580 23759 tablet_server.cc:179] TabletServer@127.23.51.193:0 shutting down...
I20260812 06:20:20.255771 23932 maintenance_manager.cc:643] P a6143224c80744518627e2633912fca5: FlushDeltaMemStoresOp(484e6dcb006448eba0b33371392e1851) complete. Timing: real 0.040s	user 0.023s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17681,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.256484 23759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:20.256839 23759 tablet_replica.cc:333] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5: stopping tablet replica
I20260812 06:20:20.257081 23759 raft_consensus.cc:2243] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.257375 23759 raft_consensus.cc:2272] T 484e6dcb006448eba0b33371392e1851 P a6143224c80744518627e2633912fca5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.272727 23759 tablet_server.cc:196] TabletServer@127.23.51.193:0 shutdown complete.
I20260812 06:20:20.277541 23759 master.cc:562] Master@127.23.51.254:39321 shutting down...
I20260812 06:20:20.280937 23759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:20.281129 23759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:20.281230 23759 tablet_replica.cc:333] T 00000000000000000000000000000000 P af1c9f1df31f4d84b5aa0b74690ced35: stopping tablet replica
I20260812 06:20:20.293931 23759 master.cc:584] Master@127.23.51.254:39321 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5151 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:20.385356 23759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.51.254:38875
I20260812 06:20:20.385763 23759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:20.388058 24094 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:20:20.388180 23759 server_base.cc:1061] running on GCE node
W20260812 06:20:20.388268 24098 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:20:20.388202 24093 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:20:20.388538 23759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:20.388615 23759 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:20:20.388635 23759 hybrid_clock.cc:648] HybridClock initialized: now 1786515620388635 us; error 0 us; skew 500 ppm
I20260812 06:20:20.392462 23759 webserver.cc:533] Webserver started at http://127.23.51.254:39507/ using document root <none> and password file <none>
I20260812 06:20:20.392656 23759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:20.392725 23759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:20.392812 23759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:20.393285 23759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/master-0-root/instance:
uuid: "32088e26b4594eb0ab68e08c6ceec789"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-rmhg"
I20260812 06:20:20.394953 23759 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:20.396004 24109 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:20:20.396267 23759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:20.396349 23759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/master-0-root
uuid: "32088e26b4594eb0ab68e08c6ceec789"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-rmhg"
I20260812 06:20:20.396421 23759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-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:20:20.413131 23759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:20.413645 23759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:20.417922 23759 rpc_server.cc:307] RPC server started. Bound to: 127.23.51.254:38875
I20260812 06:20:20.417948 24213 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.51.254:38875 every 8 connection(s)
I20260812 06:20:20.418839 24215 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:20:20.420675 24215 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789: Bootstrap starting.
I20260812 06:20:20.421586 24215 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:20.422699 24215 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789: No bootstrap required, opened a new log
I20260812 06:20:20.423091 24215 raft_consensus.cc:359] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER }
I20260812 06:20:20.423187 24215 raft_consensus.cc:385] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:20.423209 24215 raft_consensus.cc:740] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 32088e26b4594eb0ab68e08c6ceec789, State: Initialized, Role: FOLLOWER
I20260812 06:20:20.423316 24215 consensus_queue.cc:260] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [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: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER }
I20260812 06:20:20.423369 24215 raft_consensus.cc:399] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:20.423394 24215 raft_consensus.cc:493] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:20.423424 24215 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:20.424161 24215 raft_consensus.cc:515] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER }
I20260812 06:20:20.424288 24215 leader_election.cc:304] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [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: 32088e26b4594eb0ab68e08c6ceec789; no voters: 
I20260812 06:20:20.424463 24215 leader_election.cc:290] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:20.424620 24220 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:20.424815 24220 raft_consensus.cc:697] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 1 LEADER]: Becoming Leader. State: Replica: 32088e26b4594eb0ab68e08c6ceec789, State: Running, Role: LEADER
I20260812 06:20:20.424928 24215 sys_catalog.cc:565] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:20.424968 24220 consensus_queue.cc:237] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [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: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER }
I20260812 06:20:20.425469 24221 sys_catalog.cc:455] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "32088e26b4594eb0ab68e08c6ceec789" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER } }
I20260812 06:20:20.425515 24222 sys_catalog.cc:455] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 32088e26b4594eb0ab68e08c6ceec789. Latest consensus state: current_term: 1 leader_uuid: "32088e26b4594eb0ab68e08c6ceec789" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "32088e26b4594eb0ab68e08c6ceec789" member_type: VOTER } }
I20260812 06:20:20.425660 24222 sys_catalog.cc:458] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:20.425931 24230 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:20.426142 24221 sys_catalog.cc:458] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:20.426895 24230 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:20.427062 23759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:20.428917 24230 catalog_manager.cc:1383] Generated new cluster ID: 324fb2baf5c5426086b99cfad7ce9bc5
I20260812 06:20:20.428979 24230 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:20.434404 24230 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:20.435014 24230 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:20.442655 24230 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789: Generated new TSK 0
I20260812 06:20:20.442862 24230 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:20.459738 23759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:20.462067 24246 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:20:20.462301 23759 server_base.cc:1061] running on GCE node
W20260812 06:20:20.462186 24248 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:20:20.462067 24252 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:20:20.462709 23759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:20.462785 23759 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:20:20.462816 23759 hybrid_clock.cc:648] HybridClock initialized: now 1786515620462816 us; error 0 us; skew 500 ppm
I20260812 06:20:20.463909 23759 webserver.cc:533] Webserver started at http://127.23.51.193:33125/ using document root <none> and password file <none>
I20260812 06:20:20.464143 23759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:20.464206 23759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:20.464288 23759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:20.464797 23759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/instance:
uuid: "9be3e9623f104c41b3cd97260374f99d"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-rmhg"
I20260812 06:20:20.466960 23759 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:20.469529 24263 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:20:20.469805 23759 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:20:20.469882 23759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root
uuid: "9be3e9623f104c41b3cd97260374f99d"
format_stamp: "Formatted at 2026-08-12 06:20:20 on dist-test-slave-rmhg"
I20260812 06:20:20.469950 23759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-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:20:20.491312 23759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:20.491827 23759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:20.492216 23759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:20.492777 23759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:20.492821 23759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:20.492870 23759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:20.492900 23759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:20.498706 23759 rpc_server.cc:307] RPC server started. Bound to: 127.23.51.193:38953
I20260812 06:20:20.498760 24376 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.51.193:38953 every 8 connection(s)
I20260812 06:20:20.504972 24377 heartbeater.cc:344] Connected to a master server at 127.23.51.254:38875
I20260812 06:20:20.505108 24377 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:20.505421 24377 heartbeater.cc:507] Master 127.23.51.254:38875 requested a full tablet report, sending...
I20260812 06:20:20.506165 24139 ts_manager.cc:194] Registered new tserver with Master: 9be3e9623f104c41b3cd97260374f99d (127.23.51.193:38953)
I20260812 06:20:20.506922 24139 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59322
I20260812 06:20:20.507151 23759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007734796s
I20260812 06:20:20.514919 24139 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59330:
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:20:20.523976 24314 tablet_service.cc:1511] Processing CreateTablet for tablet 9cc8907a73b242f4a0a6a2196f60747a (DEFAULT_TABLE table=heavy-update-compaction-test [id=cd0cc5e8aae348ac9198501eaa120272]), partition=
I20260812 06:20:20.524279 24314 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9cc8907a73b242f4a0a6a2196f60747a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:20.526751 24405 tablet_bootstrap.cc:492] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Bootstrap starting.
I20260812 06:20:20.527648 24405 tablet_bootstrap.cc:654] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:20.528716 24405 tablet_bootstrap.cc:492] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: No bootstrap required, opened a new log
I20260812 06:20:20.528821 24405 ts_tablet_manager.cc:1403] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:20.529345 24405 raft_consensus.cc:359] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9be3e9623f104c41b3cd97260374f99d" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 38953 } }
I20260812 06:20:20.529462 24405 raft_consensus.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:20.529510 24405 raft_consensus.cc:740] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9be3e9623f104c41b3cd97260374f99d, State: Initialized, Role: FOLLOWER
I20260812 06:20:20.529657 24405 consensus_queue.cc:260] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [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: "9be3e9623f104c41b3cd97260374f99d" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 38953 } }
I20260812 06:20:20.529735 24405 raft_consensus.cc:399] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:20.529770 24405 raft_consensus.cc:493] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:20.529819 24405 raft_consensus.cc:3060] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:20.530573 24405 raft_consensus.cc:515] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9be3e9623f104c41b3cd97260374f99d" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 38953 } }
I20260812 06:20:20.530706 24405 leader_election.cc:304] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [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: 9be3e9623f104c41b3cd97260374f99d; no voters: 
I20260812 06:20:20.530915 24405 leader_election.cc:290] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:20.531023 24408 raft_consensus.cc:2804] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:20.531260 24405 ts_tablet_manager.cc:1434] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:20.531242 24408 raft_consensus.cc:697] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 1 LEADER]: Becoming Leader. State: Replica: 9be3e9623f104c41b3cd97260374f99d, State: Running, Role: LEADER
I20260812 06:20:20.531251 24377 heartbeater.cc:499] Master 127.23.51.254:38875 was elected leader, sending a full tablet report...
I20260812 06:20:20.531421 24408 consensus_queue.cc:237] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [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: "9be3e9623f104c41b3cd97260374f99d" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 38953 } }
I20260812 06:20:20.532845 24139 catalog_manager.cc:5719] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d reported cstate change: term changed from 0 to 1, leader changed from <none> to 9be3e9623f104c41b3cd97260374f99d (127.23.51.193). New cstate: current_term: 1 leader_uuid: "9be3e9623f104c41b3cd97260374f99d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9be3e9623f104c41b3cd97260374f99d" member_type: VOTER last_known_addr { host: "127.23.51.193" port: 38953 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:20.592308 23759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:20:20.750015 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=19.054940
I20260812 06:20:20.904799 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.154s	user 0.119s	sys 0.032s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":941,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38426,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1450}
I20260812 06:20:20.905584 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 20743880 bytes of WAL
I20260812 06:20:20.905841 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 2 log segments from log reader
I20260812 06:20:20.905893 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000001 (ops 1-6)
I20260812 06:20:20.905926 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000002 (ops 7-11)
I20260812 06:20:20.909729 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:20.910211 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a): 16821646 bytes on disk
I20260812 06:20:20.910902 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:20:20.911442 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:20.938911 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.027s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.939448 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:20.950238 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.950721 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:21.143996 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.193s	user 0.107s	sys 0.075s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405561,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":604,"lbm_read_time_us":12779,"lbm_reads_lt_1ms":559,"lbm_write_time_us":27187,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":288,"threads_started":5,"update_count":2450}
I20260812 06:20:21.144565 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:21.192905 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.048s	user 0.022s	sys 0.014s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17608,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.193446 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:21.204607 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.205257 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:21.386104 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.181s	user 0.124s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":906,"lbm_read_time_us":12390,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25163,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:20:21.386620 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:21.437824 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.051s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.438390 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:21.454836 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.455340 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:21.603255 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.148s	user 0.090s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":9122,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28459,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:20:21.603808 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=11.118625
I20260812 06:20:21.639834 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14814,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.640604 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:21.654816 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.655287 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:21.783757 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.128s	user 0.097s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":354,"lbm_read_time_us":8745,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24965,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:20:21.784296 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=10.126437
I20260812 06:20:21.823894 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.039s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14160,"lbm_writes_lt_1ms":303,"mutex_wait_us":23,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.824488 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:21.840216 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.840776 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:21.977608 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.137s	user 0.110s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":865,"lbm_read_time_us":8278,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27632,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:20:21.978133 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=10.126437
I20260812 06:20:22.032549 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.054s	user 0.018s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18547,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.033246 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:22.044108 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.044667 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:22.200241 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.155s	user 0.127s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10978,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25113,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2000}
I20260812 06:20:22.200927 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=10.126437
I20260812 06:20:22.243933 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":14630,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":1500}
I20260812 06:20:22.244608 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:22.260818 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.261375 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:22.290414 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1172,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1586,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:22.291109 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 120553322 bytes of WAL
I20260812 06:20:22.291392 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 12 log segments from log reader
I20260812 06:20:22.291450 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000003 (ops 12-16)
I20260812 06:20:22.291491 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000004 (ops 17-20)
I20260812 06:20:22.291617 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000005 (ops 21-25)
I20260812 06:20:22.291674 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000006 (ops 26-30)
I20260812 06:20:22.291707 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000007 (ops 31-34)
I20260812 06:20:22.291738 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000008 (ops 35-39)
I20260812 06:20:22.291767 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000009 (ops 40-44)
I20260812 06:20:22.291797 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000010 (ops 45-49)
I20260812 06:20:22.291827 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000011 (ops 50-54)
I20260812 06:20:22.291857 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000012 (ops 55-59)
I20260812 06:20:22.291886 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000013 (ops 60-64)
I20260812 06:20:22.291915 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000014 (ops 65-69)
I20260812 06:20:22.317278 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:22.317752 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=3.181125
I20260812 06:20:22.329321 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4007,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:22.329815 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 12017983 bytes of WAL
I20260812 06:20:22.330046 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 1 log segments from log reader
I20260812 06:20:22.330104 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000015 (ops 70-74)
I20260812 06:20:22.332796 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:22.333273 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:22.355289 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.022s	user 0.012s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5275,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.355875 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a): 472 bytes on disk
I20260812 06:20:22.356408 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.356859 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:22.563570 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.207s	user 0.140s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":12623,"lbm_read_time_us":14769,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32800,"lbm_writes_lt_1ms":643,"mutex_wait_us":2453,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:20:22.564206 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=15.087375
I20260812 06:20:22.626117 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.062s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":19072,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:22.626888 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=4.173312
I20260812 06:20:22.645795 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":5866701,"delete_count":0,"lbm_write_time_us":7261,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:20:22.646324 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:22.653609 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":1827,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:20:22.655177 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:22.853902 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.199s	user 0.127s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918163,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":556,"lbm_read_time_us":14580,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33022,"lbm_writes_lt_1ms":643,"mutex_wait_us":307,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":53376,"update_count":3000}
I20260812 06:20:22.854528 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:22.899565 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.045s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17554,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.900101 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:22.916646 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6541,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.917227 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:23.090200 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.173s	user 0.131s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":86,"lbm_read_time_us":12504,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28096,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:23.090723 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:23.146683 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.056s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.147261 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.157734 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.158179 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:23.345814 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.187s	user 0.127s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29224,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:23.346428 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:23.406008 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.059s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19497,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.406651 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.417618 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.418102 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:23.593420 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.175s	user 0.101s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":12083,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30003,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:23.594054 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=11.118625
I20260812 06:20:23.629055 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13082,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1550}
I20260812 06:20:23.630411 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.656038 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.025s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.656577 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.666653 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.667160 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:23.706089 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.039s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1242,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1585,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:23.706921 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 112692326 bytes of WAL
I20260812 06:20:23.707193 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 11 log segments from log reader
I20260812 06:20:23.707248 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000016 (ops 75-79)
I20260812 06:20:23.707289 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000017 (ops 80-84)
I20260812 06:20:23.707322 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000018 (ops 85-89)
I20260812 06:20:23.707353 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000019 (ops 90-94)
I20260812 06:20:23.707386 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000020 (ops 95-99)
I20260812 06:20:23.707417 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000021 (ops 100-104)
I20260812 06:20:23.707448 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000022 (ops 105-109)
I20260812 06:20:23.707477 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000023 (ops 110-114)
I20260812 06:20:23.707510 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000024 (ops 115-119)
I20260812 06:20:23.707541 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000025 (ops 120-124)
I20260812 06:20:23.707623 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000026 (ops 125-129)
I20260812 06:20:23.727594 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:20:23.728080 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a): 448 bytes on disk
I20260812 06:20:23.728603 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.729435 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.754551 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.025s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.755016 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:23.765663 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.766217 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:23.992895 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.227s	user 0.138s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2643,"lbm_read_time_us":14307,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33872,"lbm_writes_lt_1ms":743,"mutex_wait_us":1068,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:20:23.993618 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=18.063937
I20260812 06:20:24.045068 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.051s	user 0.022s	sys 0.025s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":22590,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:24.045681 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:24.203873 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.158s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815567,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":641,"lbm_read_time_us":12025,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26219,"lbm_writes_lt_1ms":543,"mutex_wait_us":392,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:20:24.204450 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:24.256341 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.052s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18040,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.257076 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:24.268289 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.268910 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:24.440164 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.171s	user 0.129s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":12292,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25686,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:20:24.440718 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:24.498179 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.057s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18296,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.498924 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:24.509832 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.510404 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:24.697309 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.187s	user 0.128s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1245,"lbm_read_time_us":12822,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30114,"lbm_writes_lt_1ms":543,"mutex_wait_us":335,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:24.697917 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=11.118625
I20260812 06:20:24.736615 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16131,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.737253 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:24.759588 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.022s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.760080 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:24.770390 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.770938 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:24.952009 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.181s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":640,"lbm_read_time_us":10828,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25140,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:20:24.952664 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:25.000557 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.048s	user 0.027s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16414,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.001259 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:25.013038 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.013808 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:25.159967 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.146s	user 0.119s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":11414,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27172,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38016,"update_count":2500}
I20260812 06:20:25.160566 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=10.126437
I20260812 06:20:25.190081 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.029s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12429,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.190796 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=2.188937
I20260812 06:20:25.206705 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.207370 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:25.241725 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushMRSOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.034s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1421,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1774,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:25.242550 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 124710614 bytes of WAL
I20260812 06:20:25.242834 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 12 log segments from log reader
I20260812 06:20:25.242897 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000027 (ops 130-134)
I20260812 06:20:25.242937 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000028 (ops 135-139)
I20260812 06:20:25.242980 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000029 (ops 140-144)
I20260812 06:20:25.243026 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000030 (ops 145-149)
I20260812 06:20:25.243057 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000031 (ops 150-154)
I20260812 06:20:25.243084 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000032 (ops 155-159)
I20260812 06:20:25.243113 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000033 (ops 160-164)
I20260812 06:20:25.243145 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000034 (ops 165-169)
I20260812 06:20:25.243175 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000035 (ops 170-174)
I20260812 06:20:25.243206 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000036 (ops 175-179)
I20260812 06:20:25.243232 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000037 (ops 180-184)
I20260812 06:20:25.243260 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000038 (ops 185-189)
I20260812 06:20:25.270139 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:25.270650 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a): 492 bytes on disk
I20260812 06:20:25.271118 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: UndoDeltaBlockGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.271744 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=6.157687
I20260812 06:20:25.291841 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8320,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:25.292403 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling LogGCOp(9cc8907a73b242f4a0a6a2196f60747a): free 12017954 bytes of WAL
I20260812 06:20:25.292670 24269 log_reader.cc:385] T 9cc8907a73b242f4a0a6a2196f60747a: removed 1 log segments from log reader
I20260812 06:20:25.292724 24269 log.cc:1079] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: Deleting log segment in path: /tmp/dist-test-taskXb_dlI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615210027-23759-0/minicluster-data/ts-0-root/wals/9cc8907a73b242f4a0a6a2196f60747a/wal-000000039 (ops 190-194)
I20260812 06:20:25.295150 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: LogGCOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:25.295657 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:25.476647 23759 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.884s	user 1.771s	sys 0.167s
I20260812 06:20:25.493753 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.198s	user 0.121s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":13181,"lbm_reads_lt_1ms":661,"lbm_write_time_us":31503,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:20:25.494442 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=14.095187
I20260812 06:20:25.526557 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: FlushDeltaMemStoresOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.032s	user 0.020s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":14621,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.527158 24383 maintenance_manager.cc:419] P 9be3e9623f104c41b3cd97260374f99d: Scheduling MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a): perf score=1.000000
I20260812 06:20:25.543531 23759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:20:25.544026 23759 tablet_server.cc:179] TabletServer@127.23.51.193:0 shutting down...
I20260812 06:20:25.637005 24269 maintenance_manager.cc:643] P 9be3e9623f104c41b3cd97260374f99d: MajorDeltaCompactionOp(9cc8907a73b242f4a0a6a2196f60747a) complete. Timing: real 0.110s	user 0.093s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":417,"lbm_read_time_us":8975,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20421,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:25.637779 23759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:25.638046 23759 tablet_replica.cc:333] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d: stopping tablet replica
I20260812 06:20:25.638178 23759 raft_consensus.cc:2243] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:25.638335 23759 raft_consensus.cc:2272] T 9cc8907a73b242f4a0a6a2196f60747a P 9be3e9623f104c41b3cd97260374f99d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:25.641742 23759 tablet_server.cc:196] TabletServer@127.23.51.193:0 shutdown complete.
I20260812 06:20:25.675028 23759 master.cc:562] Master@127.23.51.254:38875 shutting down...
I20260812 06:20:25.678314 23759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:25.678521 23759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:25.678588 23759 tablet_replica.cc:333] T 00000000000000000000000000000000 P 32088e26b4594eb0ab68e08c6ceec789: stopping tablet replica
I20260812 06:20:25.690953 23759 master.cc:584] Master@127.23.51.254:38875 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5392 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10545 ms total)

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