[==========] 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:19:05.653458 22281 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.194.126:38047
I20260812 06:19:05.654394 22281 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:19:05.654965 22281 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.661226 22291 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:19:05.661284 22281 server_base.cc:1061] running on GCE node
W20260812 06:19:05.661237 22292 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:19:05.661535 22295 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:19:05.662004 22281 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.662108 22281 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:19:05.662161 22281 hybrid_clock.cc:648] HybridClock initialized: now 1786515545662159 us; error 0 us; skew 500 ppm
I20260812 06:19:05.664000 22281 webserver.cc:533] Webserver started at http://127.21.194.126:40237/ using document root <none> and password file <none>
I20260812 06:19:05.664530 22281 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.664590 22281 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.664865 22281 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.666414 22281 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/master-0-root/instance:
uuid: "eee207738d2146208b5d589b828123b1"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-92m1"
I20260812 06:19:05.669831 22281 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:05.671802 22300 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:19:05.672724 22281 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:05.672852 22281 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/master-0-root
uuid: "eee207738d2146208b5d589b828123b1"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-92m1"
I20260812 06:19:05.672951 22281 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-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:19:05.700502 22281 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.701126 22281 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:19:05.701309 22281 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.708509 22281 rpc_server.cc:307] RPC server started. Bound to: 127.21.194.126:38047
I20260812 06:19:05.708528 22388 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.194.126:38047 every 8 connection(s)
I20260812 06:19:05.710791 22389 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:19:05.716236 22389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: Bootstrap starting.
I20260812 06:19:05.718508 22389 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.719432 22389 log.cc:826] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:05.721063 22389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: No bootstrap required, opened a new log
I20260812 06:19:05.723793 22389 raft_consensus.cc:359] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee207738d2146208b5d589b828123b1" member_type: VOTER }
I20260812 06:19:05.723944 22389 raft_consensus.cc:385] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.724047 22389 raft_consensus.cc:740] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eee207738d2146208b5d589b828123b1, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.724619 22389 consensus_queue.cc:260] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [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: "eee207738d2146208b5d589b828123b1" member_type: VOTER }
I20260812 06:19:05.724779 22389 raft_consensus.cc:399] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.724849 22389 raft_consensus.cc:493] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.724995 22389 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.725752 22389 raft_consensus.cc:515] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee207738d2146208b5d589b828123b1" member_type: VOTER }
I20260812 06:19:05.726184 22389 leader_election.cc:304] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [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: eee207738d2146208b5d589b828123b1; no voters: 
I20260812 06:19:05.726505 22389 leader_election.cc:290] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.726679 22392 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.726948 22392 raft_consensus.cc:697] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 1 LEADER]: Becoming Leader. State: Replica: eee207738d2146208b5d589b828123b1, State: Running, Role: LEADER
I20260812 06:19:05.727377 22392 consensus_queue.cc:237] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [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: "eee207738d2146208b5d589b828123b1" member_type: VOTER }
I20260812 06:19:05.727535 22389 sys_catalog.cc:565] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:05.729272 22397 sys_catalog.cc:455] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader eee207738d2146208b5d589b828123b1. Latest consensus state: current_term: 1 leader_uuid: "eee207738d2146208b5d589b828123b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee207738d2146208b5d589b828123b1" member_type: VOTER } }
I20260812 06:19:05.729295 22396 sys_catalog.cc:455] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eee207738d2146208b5d589b828123b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee207738d2146208b5d589b828123b1" member_type: VOTER } }
I20260812 06:19:05.729393 22397 sys_catalog.cc:458] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.729393 22396 sys_catalog.cc:458] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.730002 22281 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:05.732122 22419 catalog_manager.cc:1594] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:05.732236 22419 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:05.732307 22413 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:05.733050 22413 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:05.737815 22413 catalog_manager.cc:1383] Generated new cluster ID: a0a3f1e5bd8548e58a3dbb4eb253ff8e
I20260812 06:19:05.737890 22413 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:05.755597 22413 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:05.756837 22413 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:05.777338 22413 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: Generated new TSK 0
I20260812 06:19:05.778002 22413 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:05.795122 22281 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.797942 22430 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:19:05.798110 22281 server_base.cc:1061] running on GCE node
W20260812 06:19:05.797946 22425 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:19:05.797998 22426 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:19:05.798413 22281 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.798485 22281 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:19:05.798513 22281 hybrid_clock.cc:648] HybridClock initialized: now 1786515545798512 us; error 0 us; skew 500 ppm
I20260812 06:19:05.799487 22281 webserver.cc:533] Webserver started at http://127.21.194.65:33087/ using document root <none> and password file <none>
I20260812 06:19:05.799669 22281 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.799738 22281 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.799816 22281 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.800206 22281 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/instance:
uuid: "2399813255d8418eb9a80c741dc05e27"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-92m1"
I20260812 06:19:05.801699 22281 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:05.802698 22437 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:19:05.802948 22281 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:05.803023 22281 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root
uuid: "2399813255d8418eb9a80c741dc05e27"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-92m1"
I20260812 06:19:05.803113 22281 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-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:19:05.821102 22281 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.821556 22281 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.822063 22281 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:05.822897 22281 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:05.822947 22281 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.823014 22281 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:05.823052 22281 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.830035 22281 rpc_server.cc:307] RPC server started. Bound to: 127.21.194.65:40245
I20260812 06:19:05.830118 22540 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.194.65:40245 every 8 connection(s)
I20260812 06:19:05.843833 22542 heartbeater.cc:344] Connected to a master server at 127.21.194.126:38047
I20260812 06:19:05.844115 22542 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:05.844604 22542 heartbeater.cc:507] Master 127.21.194.126:38047 requested a full tablet report, sending...
I20260812 06:19:05.846016 22332 ts_manager.cc:194] Registered new tserver with Master: 2399813255d8418eb9a80c741dc05e27 (127.21.194.65:40245)
I20260812 06:19:05.846292 22281 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015608786s
I20260812 06:19:05.847517 22332 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51426
I20260812 06:19:05.856390 22332 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51436:
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:19:05.870645 22484 tablet_service.cc:1511] Processing CreateTablet for tablet 2f48607ef0f6463e8f54215f80006224 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f890be80dda34e7e898f9e2faef9526d]), partition=
I20260812 06:19:05.871124 22484 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2f48607ef0f6463e8f54215f80006224. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:05.874022 22560 tablet_bootstrap.cc:492] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Bootstrap starting.
I20260812 06:19:05.875455 22560 tablet_bootstrap.cc:654] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.876590 22560 tablet_bootstrap.cc:492] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: No bootstrap required, opened a new log
I20260812 06:19:05.876672 22560 ts_tablet_manager.cc:1403] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:05.877148 22560 raft_consensus.cc:359] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2399813255d8418eb9a80c741dc05e27" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 40245 } }
I20260812 06:19:05.877245 22560 raft_consensus.cc:385] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.877270 22560 raft_consensus.cc:740] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2399813255d8418eb9a80c741dc05e27, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.877449 22560 consensus_queue.cc:260] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [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: "2399813255d8418eb9a80c741dc05e27" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 40245 } }
I20260812 06:19:05.877539 22560 raft_consensus.cc:399] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.877585 22560 raft_consensus.cc:493] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.877651 22560 raft_consensus.cc:3060] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.878374 22560 raft_consensus.cc:515] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2399813255d8418eb9a80c741dc05e27" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 40245 } }
I20260812 06:19:05.878521 22560 leader_election.cc:304] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [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: 2399813255d8418eb9a80c741dc05e27; no voters: 
I20260812 06:19:05.878734 22560 leader_election.cc:290] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.878861 22563 raft_consensus.cc:2804] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.879128 22563 raft_consensus.cc:697] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 1 LEADER]: Becoming Leader. State: Replica: 2399813255d8418eb9a80c741dc05e27, State: Running, Role: LEADER
I20260812 06:19:05.879185 22560 ts_tablet_manager.cc:1434] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:05.879345 22563 consensus_queue.cc:237] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [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: "2399813255d8418eb9a80c741dc05e27" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 40245 } }
I20260812 06:19:05.879724 22542 heartbeater.cc:499] Master 127.21.194.126:38047 was elected leader, sending a full tablet report...
I20260812 06:19:05.881855 22332 catalog_manager.cc:5719] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2399813255d8418eb9a80c741dc05e27 (127.21.194.65). New cstate: current_term: 1 leader_uuid: "2399813255d8418eb9a80c741dc05e27" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2399813255d8418eb9a80c741dc05e27" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 40245 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:05.945209 22281 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.021s	sys 0.003s
I20260812 06:19:06.081096 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushMRSOp(2f48607ef0f6463e8f54215f80006224): perf score=19.054940
I20260812 06:19:06.254717 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushMRSOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.173s	user 0.131s	sys 0.040s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":182,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":713,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45698,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":179072,"thread_start_us":113,"threads_started":1,"update_count":1550}
I20260812 06:19:06.256083 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling LogGCOp(2f48607ef0f6463e8f54215f80006224): free 20743880 bytes of WAL
I20260812 06:19:06.256448 22442 log_reader.cc:385] T 2f48607ef0f6463e8f54215f80006224: removed 2 log segments from log reader
I20260812 06:19:06.256556 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000001 (ops 1-6)
I20260812 06:19:06.256688 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000002 (ops 7-11)
I20260812 06:19:06.263644 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: LogGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.007s	user 0.000s	sys 0.007s Metrics: {}
I20260812 06:19:06.264021 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224): 16411395 bytes on disk
I20260812 06:19:06.264572 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.264997 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.289458 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.024s	user 0.008s	sys 0.007s 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:19:06.289913 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.299633 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.300031 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:06.496359 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.196s	user 0.125s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":852,"lbm_read_time_us":13054,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31870,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":376,"threads_started":5,"update_count":2500}
I20260812 06:19:06.497031 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=11.118625
I20260812 06:19:06.541888 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.045s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17717,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1550}
I20260812 06:19:06.542457 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.556438 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.556850 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.567368 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4116,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.567974 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:06.745256 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.177s	user 0.099s	sys 0.071s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":456,"lbm_read_time_us":11298,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30690,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:19:06.746064 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:06.778424 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.032s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14131,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.779034 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.793598 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.794152 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:06.919281 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.125s	user 0.088s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":716,"lbm_read_time_us":9049,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24500,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":37248,"update_count":2000}
I20260812 06:19:06.920032 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:06.953820 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.034s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.954253 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:06.964561 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.965111 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:07.095997 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.131s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25643,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:19:07.096763 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:07.148793 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.052s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15848,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.149395 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.161816 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.162345 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:07.301674 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.139s	user 0.099s	sys 0.036s 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":524,"lbm_read_time_us":10984,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22822,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.302191 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=11.118625
I20260812 06:19:07.347469 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.045s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15518,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:07.348237 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.363651 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6135,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.364089 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:07.512521 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.148s	user 0.108s	sys 0.040s 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":266,"lbm_read_time_us":10670,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25659,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:19:07.513126 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:07.564174 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.051s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:19:07.564713 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.579479 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.580034 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushMRSOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:07.613353 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushMRSOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2010,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:07.614113 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling LogGCOp(2f48607ef0f6463e8f54215f80006224): free 124257248 bytes of WAL
I20260812 06:19:07.614337 22442 log_reader.cc:385] T 2f48607ef0f6463e8f54215f80006224: removed 12 log segments from log reader
I20260812 06:19:07.614387 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000003 (ops 12-16)
I20260812 06:19:07.614414 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000004 (ops 17-21)
I20260812 06:19:07.614480 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000005 (ops 22-26)
I20260812 06:19:07.614522 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000006 (ops 27-31)
I20260812 06:19:07.614565 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000007 (ops 32-36)
I20260812 06:19:07.614614 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000008 (ops 37-40)
I20260812 06:19:07.614653 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000009 (ops 41-45)
I20260812 06:19:07.614714 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000010 (ops 46-50)
I20260812 06:19:07.614756 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000011 (ops 51-55)
I20260812 06:19:07.614794 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000012 (ops 56-60)
I20260812 06:19:07.614835 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000013 (ops 61-65)
I20260812 06:19:07.614882 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000014 (ops 66-70)
I20260812 06:19:07.641471 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: LogGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:07.641858 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=3.181125
I20260812 06:19:07.662974 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.663496 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.678089 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5402,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.678673 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:07.866176 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.187s	user 0.110s	sys 0.072s 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":7556,"lbm_read_time_us":13665,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32829,"lbm_writes_lt_1ms":643,"mutex_wait_us":2474,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:07.866973 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224): 471 bytes on disk
I20260812 06:19:07.867636 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.868322 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:07.905145 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.905655 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.940073 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.034s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.940538 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:07.951468 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.951892 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:08.122938 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.171s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":91,"lbm_read_time_us":12950,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29918,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:08.124284 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:08.156057 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.032s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13912,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.156656 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:08.170295 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.170751 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:08.300771 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.130s	user 0.096s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":8268,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24678,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:08.301605 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:08.347081 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.045s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":15250,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.347748 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:08.358528 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.359105 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:08.487604 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.128s	user 0.091s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672282,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":651,"lbm_read_time_us":8876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25060,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:08.488291 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:08.534713 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.046s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21063,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.535419 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:08.558557 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.023s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.559303 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:08.701292 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.142s	user 0.112s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":7190,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30142,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:19:08.701936 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=10.126437
I20260812 06:19:08.765815 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.064s	user 0.034s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18468,"lbm_writes_lt_1ms":303,"mutex_wait_us":1,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.766453 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:08.785341 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.785841 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:08.943337 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.157s	user 0.104s	sys 0.052s 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":812,"lbm_read_time_us":14478,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24286,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:08.944126 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=11.118625
I20260812 06:19:08.975459 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.031s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":13322,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:19:08.975996 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:08.989080 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4919,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:08.989641 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:09.117002 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.127s	user 0.080s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":8876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25398,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:19:09.118932 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=11.118625
I20260812 06:19:09.154407 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.035s	user 0.026s	sys 0.006s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15045,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.155220 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:09.169096 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5447,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.169773 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushMRSOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:09.201704 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushMRSOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1139,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1640,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:09.202893 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling LogGCOp(2f48607ef0f6463e8f54215f80006224): free 121459505 bytes of WAL
I20260812 06:19:09.203176 22442 log_reader.cc:385] T 2f48607ef0f6463e8f54215f80006224: removed 12 log segments from log reader
I20260812 06:19:09.203296 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000015 (ops 71-75)
I20260812 06:19:09.203356 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000016 (ops 76-80)
I20260812 06:19:09.203405 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000017 (ops 81-85)
I20260812 06:19:09.203449 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000018 (ops 86-90)
I20260812 06:19:09.203487 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000019 (ops 91-95)
I20260812 06:19:09.203547 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000020 (ops 96-100)
I20260812 06:19:09.203609 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000021 (ops 101-105)
I20260812 06:19:09.203648 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000022 (ops 106-110)
I20260812 06:19:09.203732 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000023 (ops 111-115)
I20260812 06:19:09.203785 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000024 (ops 116-120)
I20260812 06:19:09.203832 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000025 (ops 121-125)
I20260812 06:19:09.203871 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000026 (ops 126-130)
I20260812 06:19:09.233078 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: LogGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:09.234598 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224): 483 bytes on disk
I20260812 06:19:09.235152 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.235863 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=6.157687
I20260812 06:19:09.268436 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.032s	user 0.026s	sys 0.005s Metrics: {"bytes_written":7712790,"delete_count":0,"lbm_write_time_us":13441,"lbm_writes_lt_1ms":191,"reinsert_count":0,"update_count":940}
I20260812 06:19:09.269217 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling LogGCOp(2f48607ef0f6463e8f54215f80006224): free 11564893 bytes of WAL
I20260812 06:19:09.269544 22442 log_reader.cc:385] T 2f48607ef0f6463e8f54215f80006224: removed 1 log segments from log reader
I20260812 06:19:09.269639 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000027 (ops 131-134)
I20260812 06:19:09.272779 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: LogGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:09.273228 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:09.539919 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.266s	user 0.219s	sys 0.044s Metrics: {"cfile_cache_miss":621,"cfile_cache_miss_bytes":28384925,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":222,"lbm_read_time_us":17316,"lbm_reads_lt_1ms":657,"lbm_write_time_us":46613,"lbm_writes_lt_1ms":631,"mutex_wait_us":52,"peak_mem_usage":74009668,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":81,"threads_started":1,"update_count":2940}
I20260812 06:19:09.543160 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=19.056125
I20260812 06:19:09.629345 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.085s	user 0.063s	sys 0.016s Metrics: {"bytes_written":21004608,"delete_count":0,"lbm_write_time_us":36207,"lbm_writes_lt_1ms":515,"reinsert_count":0,"update_count":2560}
I20260812 06:19:09.630026 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=6.157687
I20260812 06:19:09.653218 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8629,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:09.654006 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:09.906510 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.252s	user 0.163s	sys 0.077s Metrics: {"cfile_cache_miss":744,"cfile_cache_miss_bytes":33471808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":24172,"lbm_reads_lt_1ms":784,"lbm_write_time_us":37601,"lbm_writes_lt_1ms":755,"mutex_wait_us":348,"peak_mem_usage":89501848,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3560}
I20260812 06:19:09.907156 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=18.063937
I20260812 06:19:09.974121 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.067s	user 0.042s	sys 0.016s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25492,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.974634 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:09.986007 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.986492 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:10.204167 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.217s	user 0.146s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":16210,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39501,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3000}
I20260812 06:19:10.204821 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=14.095187
I20260812 06:19:10.250507 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.045s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20565,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.251044 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:10.261287 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.261706 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:10.448626 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.187s	user 0.158s	sys 0.028s 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":931,"lbm_read_time_us":12599,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33167,"lbm_writes_lt_1ms":543,"mutex_wait_us":123,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:10.449393 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=14.095187
I20260812 06:19:10.506223 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.057s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24823,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.506795 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:10.518703 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.519317 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:10.704052 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.185s	user 0.100s	sys 0.077s 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":744,"lbm_read_time_us":12523,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31381,"lbm_writes_lt_1ms":543,"mutex_wait_us":86,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:19:10.704667 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=14.095187
I20260812 06:19:10.763621 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.059s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18358,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.764119 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:10.774699 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.775182 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushMRSOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:10.806828 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushMRSOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1214,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1531,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":896}
I20260812 06:19:10.807634 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224): 472 bytes on disk
I20260812 06:19:10.808171 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: UndoDeltaBlockGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.808772 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224): perf score=1.000000
I20260812 06:19:10.972736 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: MajorDeltaCompactionOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.164s	user 0.129s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":12282,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29191,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:10.973654 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling LogGCOp(2f48607ef0f6463e8f54215f80006224): free 116849774 bytes of WAL
I20260812 06:19:10.974407 22442 log_reader.cc:385] T 2f48607ef0f6463e8f54215f80006224: removed 12 log segments from log reader
I20260812 06:19:10.974594 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000028 (ops 135-139)
I20260812 06:19:10.974753 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000029 (ops 140-144)
I20260812 06:19:10.974861 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000030 (ops 145-148)
I20260812 06:19:10.975010 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000031 (ops 149-153)
I20260812 06:19:10.975121 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000032 (ops 154-158)
I20260812 06:19:10.975265 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000033 (ops 159-162)
I20260812 06:19:10.975368 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000034 (ops 163-167)
I20260812 06:19:10.975513 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000035 (ops 168-172)
I20260812 06:19:10.975616 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000036 (ops 173-177)
I20260812 06:19:10.975724 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000037 (ops 178-182)
I20260812 06:19:10.975868 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000038 (ops 183-186)
I20260812 06:19:10.975989 22442 log.cc:1079] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/2f48607ef0f6463e8f54215f80006224/wal-000000039 (ops 187-191)
I20260812 06:19:11.012789 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: LogGCOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.039s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:19:11.013227 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=14.095187
I20260812 06:19:11.032919 22281 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.088s	user 1.867s	sys 0.175s
I20260812 06:19:11.059348 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.046s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17575,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.059934 22543 maintenance_manager.cc:419] P 2399813255d8418eb9a80c741dc05e27: Scheduling FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224): perf score=2.188937
I20260812 06:19:11.068109 22281 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.035s	user 0.003s	sys 0.000s
I20260812 06:19:11.068749 22281 tablet_server.cc:179] TabletServer@127.21.194.65:0 shutting down...
I20260812 06:19:11.075315 22442 maintenance_manager.cc:643] P 2399813255d8418eb9a80c741dc05e27: FlushDeltaMemStoresOp(2f48607ef0f6463e8f54215f80006224) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.075814 22281 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:11.076174 22281 tablet_replica.cc:333] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27: stopping tablet replica
I20260812 06:19:11.076409 22281 raft_consensus.cc:2243] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:11.076648 22281 raft_consensus.cc:2272] T 2f48607ef0f6463e8f54215f80006224 P 2399813255d8418eb9a80c741dc05e27 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:11.081981 22281 tablet_server.cc:196] TabletServer@127.21.194.65:0 shutdown complete.
I20260812 06:19:11.086238 22281 master.cc:562] Master@127.21.194.126:38047 shutting down...
I20260812 06:19:11.090672 22281 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:11.090840 22281 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:11.090926 22281 tablet_replica.cc:333] T 00000000000000000000000000000000 P eee207738d2146208b5d589b828123b1: stopping tablet replica
I20260812 06:19:11.103483 22281 master.cc:584] Master@127.21.194.126:38047 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5542 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:11.195796 22281 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.194.126:43679
I20260812 06:19:11.196323 22281 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:11.199059 22592 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:19:11.199158 22281 server_base.cc:1061] running on GCE node
W20260812 06:19:11.199298 22596 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:19:11.199117 22591 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:19:11.199576 22281 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:11.199620 22281 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:19:11.199636 22281 hybrid_clock.cc:648] HybridClock initialized: now 1786515551199636 us; error 0 us; skew 500 ppm
I20260812 06:19:11.200454 22281 webserver.cc:533] Webserver started at http://127.21.194.126:32967/ using document root <none> and password file <none>
I20260812 06:19:11.200640 22281 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:11.200692 22281 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:11.200794 22281 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:11.201201 22281 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/master-0-root/instance:
uuid: "e99ebf67da8d468fb26e45e7a520ed25"
format_stamp: "Formatted at 2026-08-12 06:19:11 on dist-test-slave-92m1"
I20260812 06:19:11.202766 22281 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:11.203873 22605 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:19:11.204157 22281 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:11.204252 22281 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/master-0-root
uuid: "e99ebf67da8d468fb26e45e7a520ed25"
format_stamp: "Formatted at 2026-08-12 06:19:11 on dist-test-slave-92m1"
I20260812 06:19:11.204344 22281 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-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:19:11.224486 22281 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:11.224879 22281 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:11.229600 22281 rpc_server.cc:307] RPC server started. Bound to: 127.21.194.126:43679
I20260812 06:19:11.232311 22687 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.194.126:43679 every 8 connection(s)
I20260812 06:19:11.235293 22688 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:19:11.241879 22688 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25: Bootstrap starting.
I20260812 06:19:11.242697 22688 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:11.243765 22688 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25: No bootstrap required, opened a new log
I20260812 06:19:11.244184 22688 raft_consensus.cc:359] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER }
I20260812 06:19:11.244272 22688 raft_consensus.cc:385] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:11.244295 22688 raft_consensus.cc:740] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e99ebf67da8d468fb26e45e7a520ed25, State: Initialized, Role: FOLLOWER
I20260812 06:19:11.244493 22688 consensus_queue.cc:260] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [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: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER }
I20260812 06:19:11.244568 22688 raft_consensus.cc:399] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:11.244637 22688 raft_consensus.cc:493] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:11.244716 22688 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:11.245410 22688 raft_consensus.cc:515] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER }
I20260812 06:19:11.245561 22688 leader_election.cc:304] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [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: e99ebf67da8d468fb26e45e7a520ed25; no voters: 
I20260812 06:19:11.245790 22688 leader_election.cc:290] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:11.245872 22695 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:11.246083 22695 raft_consensus.cc:697] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 1 LEADER]: Becoming Leader. State: Replica: e99ebf67da8d468fb26e45e7a520ed25, State: Running, Role: LEADER
I20260812 06:19:11.246284 22688 sys_catalog.cc:565] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:11.246258 22695 consensus_queue.cc:237] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [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: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER }
I20260812 06:19:11.246747 22695 sys_catalog.cc:455] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e99ebf67da8d468fb26e45e7a520ed25. Latest consensus state: current_term: 1 leader_uuid: "e99ebf67da8d468fb26e45e7a520ed25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER } }
I20260812 06:19:11.246981 22695 sys_catalog.cc:458] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:11.246904 22697 sys_catalog.cc:455] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e99ebf67da8d468fb26e45e7a520ed25" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e99ebf67da8d468fb26e45e7a520ed25" member_type: VOTER } }
I20260812 06:19:11.247300 22697 sys_catalog.cc:458] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:11.247613 22709 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:11.248639 22709 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:11.248858 22281 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:11.250923 22709 catalog_manager.cc:1383] Generated new cluster ID: 7d9822d32758458b8161a004c7d10a34
I20260812 06:19:11.250995 22709 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:11.275869 22709 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:11.276582 22709 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:11.283510 22709 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25: Generated new TSK 0
I20260812 06:19:11.283694 22709 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:11.313244 22281 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:11.315366 22736 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:19:11.315366 22733 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:19:11.315603 22281 server_base.cc:1061] running on GCE node
W20260812 06:19:11.315622 22731 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:19:11.315943 22281 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:11.316009 22281 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:19:11.316035 22281 hybrid_clock.cc:648] HybridClock initialized: now 1786515551316034 us; error 0 us; skew 500 ppm
I20260812 06:19:11.316860 22281 webserver.cc:533] Webserver started at http://127.21.194.65:38681/ using document root <none> and password file <none>
I20260812 06:19:11.317098 22281 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:11.317169 22281 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:11.317246 22281 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:11.317627 22281 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/instance:
uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847"
format_stamp: "Formatted at 2026-08-12 06:19:11 on dist-test-slave-92m1"
I20260812 06:19:11.319059 22281 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:11.320013 22742 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:19:11.320268 22281 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:11.320356 22281 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root
uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847"
format_stamp: "Formatted at 2026-08-12 06:19:11 on dist-test-slave-92m1"
I20260812 06:19:11.320442 22281 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-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:19:11.328989 22281 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:11.329316 22281 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:11.329600 22281 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:11.330039 22281 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:11.330098 22281 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:11.330156 22281 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:11.330190 22281 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:11.334537 22281 rpc_server.cc:307] RPC server started. Bound to: 127.21.194.65:35713
I20260812 06:19:11.335151 22847 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.194.65:35713 every 8 connection(s)
I20260812 06:19:11.343564 22848 heartbeater.cc:344] Connected to a master server at 127.21.194.126:43679
I20260812 06:19:11.343664 22848 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:11.343854 22848 heartbeater.cc:507] Master 127.21.194.126:43679 requested a full tablet report, sending...
I20260812 06:19:11.344589 22634 ts_manager.cc:194] Registered new tserver with Master: 548fb6876a6f4b9e88a7ea2c3ddb6847 (127.21.194.65:35713)
I20260812 06:19:11.345393 22281 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010018232s
I20260812 06:19:11.345534 22634 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56662
I20260812 06:19:11.352584 22634 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56666:
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:19:11.361511 22787 tablet_service.cc:1511] Processing CreateTablet for tablet 258424f624b34beda7b99a05df9b2ee0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=848e1bea7cab4651810005dd4fde2d78]), partition=
I20260812 06:19:11.361804 22787 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 258424f624b34beda7b99a05df9b2ee0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:11.364023 22870 tablet_bootstrap.cc:492] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Bootstrap starting.
I20260812 06:19:11.364951 22870 tablet_bootstrap.cc:654] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:11.366096 22870 tablet_bootstrap.cc:492] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: No bootstrap required, opened a new log
I20260812 06:19:11.366215 22870 ts_tablet_manager.cc:1403] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:11.366681 22870 raft_consensus.cc:359] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 35713 } }
I20260812 06:19:11.366793 22870 raft_consensus.cc:385] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:11.366843 22870 raft_consensus.cc:740] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 548fb6876a6f4b9e88a7ea2c3ddb6847, State: Initialized, Role: FOLLOWER
I20260812 06:19:11.367035 22870 consensus_queue.cc:260] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [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: "548fb6876a6f4b9e88a7ea2c3ddb6847" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 35713 } }
I20260812 06:19:11.367144 22870 raft_consensus.cc:399] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:11.367228 22870 raft_consensus.cc:493] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:11.367278 22870 raft_consensus.cc:3060] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:11.367974 22870 raft_consensus.cc:515] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 35713 } }
I20260812 06:19:11.368111 22870 leader_election.cc:304] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [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: 548fb6876a6f4b9e88a7ea2c3ddb6847; no voters: 
I20260812 06:19:11.368312 22870 leader_election.cc:290] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:11.368448 22873 raft_consensus.cc:2804] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:11.368644 22848 heartbeater.cc:499] Master 127.21.194.126:43679 was elected leader, sending a full tablet report...
I20260812 06:19:11.368662 22873 raft_consensus.cc:697] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 1 LEADER]: Becoming Leader. State: Replica: 548fb6876a6f4b9e88a7ea2c3ddb6847, State: Running, Role: LEADER
I20260812 06:19:11.368862 22873 consensus_queue.cc:237] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [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: "548fb6876a6f4b9e88a7ea2c3ddb6847" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 35713 } }
I20260812 06:19:11.368927 22870 ts_tablet_manager.cc:1434] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:11.370158 22634 catalog_manager.cc:5719] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 reported cstate change: term changed from 0 to 1, leader changed from <none> to 548fb6876a6f4b9e88a7ea2c3ddb6847 (127.21.194.65). New cstate: current_term: 1 leader_uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "548fb6876a6f4b9e88a7ea2c3ddb6847" member_type: VOTER last_known_addr { host: "127.21.194.65" port: 35713 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:11.431782 22281 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.011s	sys 0.012s
I20260812 06:19:11.585816 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushMRSOp(258424f624b34beda7b99a05df9b2ee0): perf score=19.054940
I20260812 06:19:11.745560 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushMRSOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.159s	user 0.121s	sys 0.035s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":683,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39692,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:11.746608 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 20743880 bytes of WAL
I20260812 06:19:11.746954 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 2 log segments from log reader
I20260812 06:19:11.747030 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000001 (ops 1-6)
I20260812 06:19:11.747104 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000002 (ops 7-11)
I20260812 06:19:11.753234 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:11.753566 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=3.181125
I20260812 06:19:11.766743 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4625,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:11.767156 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0): 16411396 bytes on disk
I20260812 06:19:11.767581 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:11.767966 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:11.777484 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.777846 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:11.973407 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.195s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774796,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":615,"lbm_read_time_us":12517,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33426,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:19:11.974113 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:12.018210 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.018677 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:12.177500 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.159s	user 0.108s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":167,"lbm_read_time_us":11671,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:12.178148 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:12.224448 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.046s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.224992 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:12.238639 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.239099 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:12.438614 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.199s	user 0.128s	sys 0.063s 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":434,"lbm_read_time_us":11597,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31947,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:12.439191 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:12.489866 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.050s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21770,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.490338 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:12.505537 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.506275 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:12.669528 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.163s	user 0.135s	sys 0.026s 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":781,"lbm_read_time_us":10100,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31655,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:12.670280 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=11.118625
I20260812 06:19:12.706017 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14844,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:12.706563 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:12.731251 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.025s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.731746 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:12.743728 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.744366 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:12.903462 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.159s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":462,"lbm_read_time_us":10557,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30516,"lbm_writes_lt_1ms":543,"mutex_wait_us":5,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:12.904114 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:12.955329 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.051s	user 0.006s	sys 0.041s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20914,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.955922 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:12.966598 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.967252 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushMRSOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:12.997776 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushMRSOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1138,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1492,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:12.998363 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 112239310 bytes of WAL
I20260812 06:19:12.998597 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 11 log segments from log reader
I20260812 06:19:12.998642 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000003 (ops 12-16)
I20260812 06:19:12.998672 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000004 (ops 17-20)
I20260812 06:19:12.998732 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000005 (ops 21-25)
I20260812 06:19:12.998770 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000006 (ops 26-30)
I20260812 06:19:12.998816 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000007 (ops 31-35)
I20260812 06:19:12.998873 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000008 (ops 36-40)
I20260812 06:19:12.998936 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000009 (ops 41-45)
I20260812 06:19:12.998980 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000010 (ops 46-50)
I20260812 06:19:12.999020 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000011 (ops 51-55)
I20260812 06:19:12.999058 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000012 (ops 56-60)
I20260812 06:19:12.999096 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000013 (ops 61-65)
I20260812 06:19:13.025236 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:13.025663 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=3.181125
I20260812 06:19:13.043735 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.018s	user 0.005s	sys 0.013s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7504,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:13.044181 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 12017932 bytes of WAL
I20260812 06:19:13.044387 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 1 log segments from log reader
I20260812 06:19:13.044432 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000014 (ops 66-70)
I20260812 06:19:13.046628 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:13.046950 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0): 462 bytes on disk
I20260812 06:19:13.047427 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0) 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:19:13.047832 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:13.069610 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.022s	user 0.009s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.070195 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:13.324661 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.254s	user 0.151s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":487,"lbm_read_time_us":18596,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42548,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13824,"thread_start_us":122,"threads_started":1,"update_count":3500}
I20260812 06:19:13.325522 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=18.063937
I20260812 06:19:13.388864 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.063s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":29312,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:13.389305 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:13.400043 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.400717 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:13.583266 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.182s	user 0.127s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":15258,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29918,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:19:13.583770 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:13.639451 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.056s	user 0.038s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23699,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.640020 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:13.651405 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.651899 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:13.833709 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.182s	user 0.113s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":13758,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30394,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:19:13.834307 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:13.894459 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.060s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20557,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.894966 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:13.905182 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.905620 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:14.086515 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.181s	user 0.123s	sys 0.048s 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":187,"lbm_read_time_us":13192,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":30173,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:19:14.087313 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=14.095187
I20260812 06:19:14.156054 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.069s	user 0.020s	sys 0.043s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23055,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.156666 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.174367 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.174943 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:14.348366 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.173s	user 0.100s	sys 0.071s 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":730,"lbm_read_time_us":12034,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29456,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:14.348906 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=11.118625
I20260812 06:19:14.394476 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.045s	user 0.033s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18898,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:14.394953 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.415282 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5538,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:14.415781 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.434823 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.019s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.435436 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushMRSOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:14.473721 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushMRSOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.038s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":131,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1033,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1930,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:14.474454 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 108535399 bytes of WAL
I20260812 06:19:14.474705 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 11 log segments from log reader
I20260812 06:19:14.474774 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000015 (ops 71-75)
I20260812 06:19:14.474828 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000016 (ops 76-80)
I20260812 06:19:14.474889 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000017 (ops 81-85)
I20260812 06:19:14.474920 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000018 (ops 86-90)
I20260812 06:19:14.474953 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000019 (ops 91-94)
I20260812 06:19:14.474989 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000020 (ops 95-99)
I20260812 06:19:14.475026 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000021 (ops 100-104)
I20260812 06:19:14.475064 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000022 (ops 105-109)
I20260812 06:19:14.475104 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000023 (ops 110-114)
I20260812 06:19:14.475143 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000024 (ops 115-118)
I20260812 06:19:14.475183 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000025 (ops 119-123)
I20260812 06:19:14.496441 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.022s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:19:14.496894 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.522995 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.026s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.523454 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.533739 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.534188 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0): 448 bytes on disk
I20260812 06:19:14.534624 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.535163 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:14.773882 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.238s	user 0.138s	sys 0.089s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1705,"lbm_read_time_us":15112,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37495,"lbm_writes_lt_1ms":743,"mutex_wait_us":277,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:14.774637 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=18.063937
I20260812 06:19:14.845692 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.071s	user 0.036s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26239,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:14.846158 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:14.857767 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.858229 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:15.083551 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.225s	user 0.179s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1646,"lbm_read_time_us":14214,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37745,"lbm_writes_lt_1ms":643,"mutex_wait_us":491,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:19:15.084162 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=18.063937
I20260812 06:19:15.158564 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.074s	user 0.040s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29319,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:15.159109 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:15.169377 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.170007 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:15.391335 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.221s	user 0.134s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1324,"lbm_read_time_us":15844,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37503,"lbm_writes_lt_1ms":643,"mutex_wait_us":354,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":3000}
I20260812 06:19:15.392045 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=16.079562
I20260812 06:19:15.446611 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.054s	user 0.039s	sys 0.012s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":24106,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:19:15.447302 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.196750
I20260812 06:19:15.468815 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.021s	user 0.010s	sys 0.001s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:15.469298 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:15.479910 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.480410 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:15.706589 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.226s	user 0.160s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":15270,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38410,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:15.707361 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=18.063937
I20260812 06:19:15.773078 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.065s	user 0.024s	sys 0.036s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28289,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:15.773605 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:15.789069 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.789844 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:15.985766 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.196s	user 0.140s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":683,"lbm_read_time_us":14210,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32654,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:19:15.987792 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=15.087375
I20260812 06:19:16.043524 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.055s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24285,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:16.044150 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:16.068310 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.024s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.068789 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=2.188937
I20260812 06:19:16.079551 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.080231 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushMRSOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:16.113847 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushMRSOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1176,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:16.114537 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 128867756 bytes of WAL
I20260812 06:19:16.114765 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 13 log segments from log reader
I20260812 06:19:16.114827 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000026 (ops 124-128)
I20260812 06:19:16.114879 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000027 (ops 129-133)
I20260812 06:19:16.114939 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000028 (ops 134-138)
I20260812 06:19:16.114987 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000029 (ops 139-142)
I20260812 06:19:16.115025 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000030 (ops 143-147)
I20260812 06:19:16.115063 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000031 (ops 148-152)
I20260812 06:19:16.115099 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000032 (ops 153-156)
I20260812 06:19:16.115137 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000033 (ops 157-161)
I20260812 06:19:16.115175 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000034 (ops 162-166)
I20260812 06:19:16.115232 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000035 (ops 167-171)
I20260812 06:19:16.115276 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000036 (ops 172-176)
I20260812 06:19:16.115314 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000037 (ops 177-180)
I20260812 06:19:16.115352 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000038 (ops 181-185)
I20260812 06:19:16.144796 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:16.145279 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0): 492 bytes on disk
I20260812 06:19:16.145753 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: UndoDeltaBlockGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.146965 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=4.173312
I20260812 06:19:16.162828 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":5374416,"delete_count":0,"lbm_write_time_us":6368,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:19:16.163388 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling LogGCOp(258424f624b34beda7b99a05df9b2ee0): free 12017952 bytes of WAL
I20260812 06:19:16.163618 22749 log_reader.cc:385] T 258424f624b34beda7b99a05df9b2ee0: removed 1 log segments from log reader
I20260812 06:19:16.163679 22749 log.cc:1079] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: Deleting log segment in path: /tmp/dist-test-taskyT20Ku/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515545643123-22281-0/minicluster-data/ts-0-root/wals/258424f624b34beda7b99a05df9b2ee0/wal-000000039 (ops 186-190)
I20260812 06:19:16.166823 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: LogGCOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:16.167200 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.196750
I20260812 06:19:16.180111 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4755,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:16.180708 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0): perf score=1.000000
I20260812 06:19:16.426932 22281 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.995s	user 1.818s	sys 0.198s
I20260812 06:19:16.431298 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: MajorDeltaCompactionOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.250s	user 0.169s	sys 0.077s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":437,"lbm_read_time_us":18836,"lbm_reads_lt_1ms":875,"lbm_write_time_us":47000,"lbm_writes_lt_1ms":843,"mutex_wait_us":76,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":101,"threads_started":1,"update_count":4000}
I20260812 06:19:16.432063 22849 maintenance_manager.cc:419] P 548fb6876a6f4b9e88a7ea2c3ddb6847: Scheduling FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0): perf score=18.063937
I20260812 06:19:16.451092 22281 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.024s	user 0.000s	sys 0.000s
I20260812 06:19:16.451635 22281 tablet_server.cc:179] TabletServer@127.21.194.65:0 shutting down...
I20260812 06:19:16.488006 22749 maintenance_manager.cc:643] P 548fb6876a6f4b9e88a7ea2c3ddb6847: FlushDeltaMemStoresOp(258424f624b34beda7b99a05df9b2ee0) complete. Timing: real 0.056s	user 0.033s	sys 0.021s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25271,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:16.488595 22281 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:16.488801 22281 tablet_replica.cc:333] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847: stopping tablet replica
I20260812 06:19:16.488945 22281 raft_consensus.cc:2243] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:16.489137 22281 raft_consensus.cc:2272] T 258424f624b34beda7b99a05df9b2ee0 P 548fb6876a6f4b9e88a7ea2c3ddb6847 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:16.492416 22281 tablet_server.cc:196] TabletServer@127.21.194.65:0 shutdown complete.
I20260812 06:19:16.506412 22281 master.cc:562] Master@127.21.194.126:43679 shutting down...
I20260812 06:19:16.509895 22281 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:16.510082 22281 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:16.510185 22281 tablet_replica.cc:333] T 00000000000000000000000000000000 P e99ebf67da8d468fb26e45e7a520ed25: stopping tablet replica
I20260812 06:19:16.522594 22281 master.cc:584] Master@127.21.194.126:43679 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5418 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10961 ms total)

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