[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:17.273645 31892 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.37.62:41777
I20260812 06:20:17.274709 31892 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:20:17.275329 31892 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:17.281868 31892 server_base.cc:1061] running on GCE node
W20260812 06:20:17.281862 31901 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:17.282097 31898 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:17.282465 31897 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:17.282986 31892 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.283123 31892 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:17.283181 31892 hybrid_clock.cc:648] HybridClock initialized: now 1786515617283177 us; error 0 us; skew 500 ppm
I20260812 06:20:17.285171 31892 webserver.cc:533] Webserver started at http://127.31.37.62:40619/ using document root <none> and password file <none>
I20260812 06:20:17.285741 31892 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.285841 31892 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.286118 31892 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.287789 31892 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/master-0-root/instance:
uuid: "6f364bb7cefb4748b15634a603a5e490"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-1zqn"
I20260812 06:20:17.291432 31892 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:20:17.293637 31906 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.294965 31892 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:17.295137 31892 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/master-0-root
uuid: "6f364bb7cefb4748b15634a603a5e490"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-1zqn"
I20260812 06:20:17.295277 31892 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:17.328534 31892 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.329372 31892 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:20:17.329610 31892 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.339080 31892 rpc_server.cc:307] RPC server started. Bound to: 127.31.37.62:41777
I20260812 06:20:17.339147 31965 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.37.62:41777 every 8 connection(s)
I20260812 06:20:17.341650 31968 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:17.347402 31968 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: Bootstrap starting.
I20260812 06:20:17.349927 31968 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.350903 31968 log.cc:826] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:17.352924 31968 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: No bootstrap required, opened a new log
I20260812 06:20:17.355741 31968 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER }
I20260812 06:20:17.355906 31968 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.356076 31968 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6f364bb7cefb4748b15634a603a5e490, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.356693 31968 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [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: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER }
I20260812 06:20:17.356863 31968 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.356935 31968 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.357116 31968 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.357967 31968 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER }
I20260812 06:20:17.358429 31968 leader_election.cc:304] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [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: 6f364bb7cefb4748b15634a603a5e490; no voters: 
I20260812 06:20:17.358776 31968 leader_election.cc:290] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.358911 31972 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.359170 31972 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 1 LEADER]: Becoming Leader. State: Replica: 6f364bb7cefb4748b15634a603a5e490, State: Running, Role: LEADER
I20260812 06:20:17.359587 31972 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [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: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER }
I20260812 06:20:17.359850 31968 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:17.361585 31973 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6f364bb7cefb4748b15634a603a5e490" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER } }
I20260812 06:20:17.361620 31975 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6f364bb7cefb4748b15634a603a5e490. Latest consensus state: current_term: 1 leader_uuid: "6f364bb7cefb4748b15634a603a5e490" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f364bb7cefb4748b15634a603a5e490" member_type: VOTER } }
I20260812 06:20:17.361723 31973 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.361723 31975 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:17.362316 31892 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:17.364248 31994 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:17.364307 31994 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:17.364377 31989 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:17.365075 31989 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:17.369721 31989 catalog_manager.cc:1383] Generated new cluster ID: ff97a0f1977b4efbaab8d890f634bbd2
I20260812 06:20:17.369793 31989 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:17.378608 31989 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:17.379464 31989 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:17.389560 31989 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: Generated new TSK 0
I20260812 06:20:17.390228 31989 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:17.395375 31892 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:17.398639 31892 server_base.cc:1061] running on GCE node
W20260812 06:20:17.398679 31998 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:17.398666 31999 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:17.399045 32002 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:17.399327 31892 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:17.399385 31892 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:17.399408 31892 hybrid_clock.cc:648] HybridClock initialized: now 1786515617399408 us; error 0 us; skew 500 ppm
I20260812 06:20:17.400404 31892 webserver.cc:533] Webserver started at http://127.31.37.1:32915/ using document root <none> and password file <none>
I20260812 06:20:17.400583 31892 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:17.400642 31892 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:17.400710 31892 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:17.401156 31892 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/instance:
uuid: "a86a625bea8144d2a1253f248a168e89"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-1zqn"
I20260812 06:20:17.403052 31892 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:17.404276 32007 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.404557 31892 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:17.404623 31892 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root
uuid: "a86a625bea8144d2a1253f248a168e89"
format_stamp: "Formatted at 2026-08-12 06:20:17 on dist-test-slave-1zqn"
I20260812 06:20:17.404711 31892 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:17.411468 31892 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:17.411908 31892 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:17.412503 31892 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:17.413393 31892 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:17.413455 31892 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.413524 31892 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:17.413563 31892 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:17.420287 31892 rpc_server.cc:307] RPC server started. Bound to: 127.31.37.1:42457
I20260812 06:20:17.420344 32081 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.37.1:42457 every 8 connection(s)
I20260812 06:20:17.434849 32082 heartbeater.cc:344] Connected to a master server at 127.31.37.62:41777
I20260812 06:20:17.435148 32082 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:17.435680 32082 heartbeater.cc:507] Master 127.31.37.62:41777 requested a full tablet report, sending...
I20260812 06:20:17.437316 31925 ts_manager.cc:194] Registered new tserver with Master: a86a625bea8144d2a1253f248a168e89 (127.31.37.1:42457)
I20260812 06:20:17.437769 31892 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016817833s
I20260812 06:20:17.439580 31925 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33354
I20260812 06:20:17.448573 31925 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33362:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:17.464480 32038 tablet_service.cc:1511] Processing CreateTablet for tablet 5389be199fb1449b954c8b1b79535916 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8aa502a24da44200be381379b82a1ff2]), partition=
I20260812 06:20:17.465080 32038 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5389be199fb1449b954c8b1b79535916. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:17.467801 32099 tablet_bootstrap.cc:492] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Bootstrap starting.
I20260812 06:20:17.468770 32099 tablet_bootstrap.cc:654] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:17.469872 32099 tablet_bootstrap.cc:492] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: No bootstrap required, opened a new log
I20260812 06:20:17.469995 32099 ts_tablet_manager.cc:1403] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:17.470424 32099 raft_consensus.cc:359] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a86a625bea8144d2a1253f248a168e89" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 42457 } }
I20260812 06:20:17.470575 32099 raft_consensus.cc:385] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:17.470660 32099 raft_consensus.cc:740] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a86a625bea8144d2a1253f248a168e89, State: Initialized, Role: FOLLOWER
I20260812 06:20:17.470857 32099 consensus_queue.cc:260] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [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: "a86a625bea8144d2a1253f248a168e89" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 42457 } }
I20260812 06:20:17.471010 32099 raft_consensus.cc:399] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:17.471068 32099 raft_consensus.cc:493] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:17.471136 32099 raft_consensus.cc:3060] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:17.471901 32099 raft_consensus.cc:515] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a86a625bea8144d2a1253f248a168e89" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 42457 } }
I20260812 06:20:17.472054 32099 leader_election.cc:304] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [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: a86a625bea8144d2a1253f248a168e89; no voters: 
I20260812 06:20:17.472317 32099 leader_election.cc:290] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:17.472409 32101 raft_consensus.cc:2804] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:17.472611 32101 raft_consensus.cc:697] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 1 LEADER]: Becoming Leader. State: Replica: a86a625bea8144d2a1253f248a168e89, State: Running, Role: LEADER
I20260812 06:20:17.472679 32099 ts_tablet_manager.cc:1434] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:20:17.472834 32101 consensus_queue.cc:237] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [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: "a86a625bea8144d2a1253f248a168e89" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 42457 } }
I20260812 06:20:17.473063 32082 heartbeater.cc:499] Master 127.31.37.62:41777 was elected leader, sending a full tablet report...
I20260812 06:20:17.475538 31925 catalog_manager.cc:5719] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 reported cstate change: term changed from 0 to 1, leader changed from <none> to a86a625bea8144d2a1253f248a168e89 (127.31.37.1). New cstate: current_term: 1 leader_uuid: "a86a625bea8144d2a1253f248a168e89" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a86a625bea8144d2a1253f248a168e89" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 42457 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:17.542600 31892 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.022s	sys 0.004s
I20260812 06:20:17.671380 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushMRSOp(5389be199fb1449b954c8b1b79535916): perf score=15.086190
I20260812 06:20:17.844045 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushMRSOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.172s	user 0.135s	sys 0.024s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":265,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":886,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41043,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":115,"threads_started":1,"update_count":1450}
I20260812 06:20:17.845139 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 20743880 bytes of WAL
I20260812 06:20:17.845443 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 2 log segments from log reader
I20260812 06:20:17.845515 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000001 (ops 1-6)
I20260812 06:20:17.845593 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000002 (ops 7-11)
I20260812 06:20:17.850076 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:17.850420 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916): 12719213 bytes on disk
I20260812 06:20:17.851035 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.851418 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:17.867892 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.868398 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:18.010782 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.142s	user 0.108s	sys 0.034s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":8356,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26832,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":357,"threads_started":5,"update_count":1950}
I20260812 06:20:18.011427 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=10.126437
I20260812 06:20:18.064288 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.053s	user 0.029s	sys 0.019s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":24491,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.064913 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:18.076721 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.077435 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:18.222645 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.145s	user 0.107s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1481,"lbm_read_time_us":10678,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27316,"lbm_writes_lt_1ms":443,"mutex_wait_us":378,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:18.223348 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=11.118625
I20260812 06:20:18.264469 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.041s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18277,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:18.264966 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:18.286586 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6183,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.287127 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:18.297825 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.298388 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:18.468466 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.170s	user 0.124s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4937,"lbm_read_time_us":12225,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31743,"lbm_writes_lt_1ms":543,"mutex_wait_us":4465,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:18.469201 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=13.103000
I20260812 06:20:18.519805 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.050s	user 0.024s	sys 0.020s Metrics: {"bytes_written":14645856,"delete_count":0,"lbm_write_time_us":21978,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":358,"reinsert_count":0,"update_count":1785}
I20260812 06:20:18.520326 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=1.196750
I20260812 06:20:18.531412 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2174483,"delete_count":0,"lbm_write_time_us":2147,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:20:18.531903 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:18.541604 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.542030 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:18.742687 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.200s	user 0.106s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774744,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":185,"lbm_read_time_us":14508,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35062,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:18.743374 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:18.800386 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23544,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.800873 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:18.811726 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.812336 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:18.989053 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.177s	user 0.126s	sys 0.045s 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":234,"lbm_read_time_us":12956,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31627,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:20:18.989741 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:19.058214 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.068s	user 0.024s	sys 0.042s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":28043,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.058853 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:19.070240 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.070709 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:19.257015 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.186s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":13898,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31509,"lbm_writes_lt_1ms":543,"mutex_wait_us":98,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:19.257709 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:19.324165 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.066s	user 0.047s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24661,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.324798 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:19.341547 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.342144 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushMRSOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:19.388752 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushMRSOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.046s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":1498,"drs_written":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1771,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:19.389636 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 133024372 bytes of WAL
I20260812 06:20:19.389882 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 13 log segments from log reader
I20260812 06:20:19.389927 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000003 (ops 12-16)
I20260812 06:20:19.389961 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000004 (ops 17-21)
I20260812 06:20:19.390026 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000005 (ops 22-26)
I20260812 06:20:19.390059 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000006 (ops 27-31)
I20260812 06:20:19.390101 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000007 (ops 32-36)
I20260812 06:20:19.390151 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000008 (ops 37-41)
I20260812 06:20:19.390192 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000009 (ops 42-46)
I20260812 06:20:19.390235 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000010 (ops 47-50)
I20260812 06:20:19.390276 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000011 (ops 51-55)
I20260812 06:20:19.390317 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000012 (ops 56-60)
I20260812 06:20:19.390357 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000013 (ops 61-65)
I20260812 06:20:19.390398 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000014 (ops 66-70)
I20260812 06:20:19.390436 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000015 (ops 71-75)
I20260812 06:20:19.418836 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:19.419281 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=3.181125
I20260812 06:20:19.434134 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.015s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:19.434665 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:19.444955 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.445451 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:19.670428 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.225s	user 0.158s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1231,"lbm_read_time_us":16340,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40499,"lbm_writes_lt_1ms":743,"mutex_wait_us":357,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:20:19.671293 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=15.087375
I20260812 06:20:19.735051 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.064s	user 0.020s	sys 0.035s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":26487,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:20:19.735651 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:19.747339 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4307782,"delete_count":0,"lbm_write_time_us":4730,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:20:19.747781 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916): 492 bytes on disk
I20260812 06:20:19.748253 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.748695 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:19.758466 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3289,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:20:19.759122 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:19.954959 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.196s	user 0.139s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1245,"lbm_read_time_us":14190,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35804,"lbm_writes_lt_1ms":643,"mutex_wait_us":351,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:20:19.955760 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:20.007483 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.051s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22514,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.008152 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:20.034597 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.026s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.035077 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:20.045893 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.046360 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:20.230280 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.184s	user 0.132s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":819,"lbm_read_time_us":12716,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38216,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":3000}
I20260812 06:20:20.231355 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=15.087375
I20260812 06:20:20.295074 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.064s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16656047,"delete_count":0,"lbm_write_time_us":29638,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2030}
I20260812 06:20:20.295579 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=3.181125
I20260812 06:20:20.314174 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.018s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4266759,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":107,"reinsert_count":0,"update_count":520}
I20260812 06:20:20.314697 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:20.325707 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.326404 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:20.511513 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.185s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1025,"lbm_read_time_us":13330,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37471,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":3000}
I20260812 06:20:20.512499 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:20.559720 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20993,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.560354 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:20.581099 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.021s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.581662 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:20.754808 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.173s	user 0.135s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":9504,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34830,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:20:20.755453 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:20.800804 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.045s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.801440 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushMRSOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:20.828339 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushMRSOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1419,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:20.829124 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 115943203 bytes of WAL
I20260812 06:20:20.829391 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 11 log segments from log reader
I20260812 06:20:20.829460 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000016 (ops 76-80)
I20260812 06:20:20.829520 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000017 (ops 81-85)
I20260812 06:20:20.829587 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000018 (ops 86-90)
I20260812 06:20:20.829638 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000019 (ops 91-95)
I20260812 06:20:20.829681 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000020 (ops 96-100)
I20260812 06:20:20.829726 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000021 (ops 101-105)
I20260812 06:20:20.829770 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000022 (ops 106-110)
I20260812 06:20:20.829814 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000023 (ops 111-115)
I20260812 06:20:20.829859 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000024 (ops 116-120)
I20260812 06:20:20.829911 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000025 (ops 121-125)
I20260812 06:20:20.829954 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000026 (ops 126-130)
I20260812 06:20:20.856302 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:20.856887 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916): 472 bytes on disk
I20260812 06:20:20.857630 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916) 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:20:20.858909 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=6.157687
I20260812 06:20:20.879788 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":7507666,"delete_count":0,"lbm_write_time_us":8369,"lbm_writes_lt_1ms":186,"reinsert_count":0,"update_count":915}
I20260812 06:20:20.880795 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 8767140 bytes of WAL
I20260812 06:20:20.881166 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 1 log segments from log reader
I20260812 06:20:20.881291 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000027 (ops 131-135)
I20260812 06:20:20.886647 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.006s	user 0.001s	sys 0.000s Metrics: {}
I20260812 06:20:20.887187 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:21.079363 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.192s	user 0.102s	sys 0.087s Metrics: {"cfile_cache_miss":615,"cfile_cache_miss_bytes":28179690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1026,"lbm_read_time_us":12715,"lbm_reads_lt_1ms":651,"lbm_write_time_us":33347,"lbm_writes_lt_1ms":626,"peak_mem_usage":72764109,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":100,"threads_started":1,"update_count":2915}
I20260812 06:20:21.080005 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=15.087375
I20260812 06:20:21.141690 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.061s	user 0.031s	sys 0.016s Metrics: {"bytes_written":17107322,"delete_count":0,"lbm_write_time_us":21816,"lbm_writes_lt_1ms":420,"reinsert_count":0,"update_count":2085}
I20260812 06:20:21.142161 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:21.152978 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.153489 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:21.346730 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.193s	user 0.143s	sys 0.050s Metrics: {"cfile_cache_miss":549,"cfile_cache_miss_bytes":25472109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":11650,"lbm_reads_lt_1ms":589,"lbm_write_time_us":35984,"lbm_writes_lt_1ms":560,"mutex_wait_us":34,"peak_mem_usage":64853879,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2585}
I20260812 06:20:21.347455 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:21.402801 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.055s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18503,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.403407 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:21.421519 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.422067 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:21.606864 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.185s	user 0.128s	sys 0.053s 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":141,"lbm_read_time_us":12980,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33253,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:20:21.607576 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:21.667534 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.060s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.668195 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:21.679101 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.679570 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:21.874235 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.194s	user 0.141s	sys 0.047s 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":141,"lbm_read_time_us":12751,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33788,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:20:21.879065 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=11.118625
I20260812 06:20:21.924145 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.045s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19345,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.924733 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:21.957404 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.032s	user 0.011s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.957962 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:21.968910 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.969398 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:22.152275 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.183s	user 0.117s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":355,"lbm_read_time_us":12945,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30136,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:20:22.153025 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=11.118625
I20260812 06:20:22.202860 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.050s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18881,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:20:22.203522 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:22.217284 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.217834 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:22.231186 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.231761 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:22.427738 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.196s	user 0.127s	sys 0.055s 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":586,"lbm_read_time_us":14846,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28084,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:20:22.428530 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=14.095187
I20260812 06:20:22.479712 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.051s	user 0.033s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23233,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.480280 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:22.493928 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.494602 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushMRSOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:22.531272 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushMRSOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.036s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1493,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1833,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:22.532478 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 121006705 bytes of WAL
I20260812 06:20:22.532742 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 12 log segments from log reader
I20260812 06:20:22.532792 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000028 (ops 136-140)
I20260812 06:20:22.532824 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000029 (ops 141-145)
I20260812 06:20:22.532887 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000030 (ops 146-150)
I20260812 06:20:22.532979 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000031 (ops 151-155)
I20260812 06:20:22.533039 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000032 (ops 156-160)
I20260812 06:20:22.533130 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000033 (ops 161-164)
I20260812 06:20:22.533201 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000034 (ops 165-169)
I20260812 06:20:22.533294 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000035 (ops 170-174)
I20260812 06:20:22.533351 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000036 (ops 175-179)
I20260812 06:20:22.533403 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000037 (ops 180-184)
I20260812 06:20:22.533466 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000038 (ops 185-189)
I20260812 06:20:22.533519 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000039 (ops 190-194)
I20260812 06:20:22.567493 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:22.568035 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=3.181125
I20260812 06:20:22.582298 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:22.582839 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling LogGCOp(5389be199fb1449b954c8b1b79535916): free 11564893 bytes of WAL
I20260812 06:20:22.583065 32013 log_reader.cc:385] T 5389be199fb1449b954c8b1b79535916: removed 1 log segments from log reader
I20260812 06:20:22.583112 32013 log.cc:1079] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/5389be199fb1449b954c8b1b79535916/wal-000000040 (ops 195-198)
I20260812 06:20:22.585454 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: LogGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:22.585779 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916): perf score=2.188937
I20260812 06:20:22.595566 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: FlushDeltaMemStoresOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.596028 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916): 482 bytes on disk
I20260812 06:20:22.596531 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: UndoDeltaBlockGCOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.597035 32084 maintenance_manager.cc:419] P a86a625bea8144d2a1253f248a168e89: Scheduling MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916): perf score=1.000000
I20260812 06:20:22.640407 31892 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.098s	user 1.899s	sys 0.146s
I20260812 06:20:22.744349 31892 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.003s	sys 0.000s
I20260812 06:20:22.745016 31892 tablet_server.cc:179] TabletServer@127.31.37.1:0 shutting down...
I20260812 06:20:22.793169 32013 maintenance_manager.cc:643] P a86a625bea8144d2a1253f248a168e89: MajorDeltaCompactionOp(5389be199fb1449b954c8b1b79535916) complete. Timing: real 0.196s	user 0.143s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":417,"lbm_read_time_us":15989,"lbm_reads_lt_1ms":770,"lbm_write_time_us":33832,"lbm_writes_lt_1ms":743,"mutex_wait_us":19,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":40832,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:20:22.794691 31892 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:22.795218 31892 tablet_replica.cc:333] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89: stopping tablet replica
I20260812 06:20:22.795534 31892 raft_consensus.cc:2243] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.795804 31892 raft_consensus.cc:2272] T 5389be199fb1449b954c8b1b79535916 P a86a625bea8144d2a1253f248a168e89 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.812718 31892 tablet_server.cc:196] TabletServer@127.31.37.1:0 shutdown complete.
I20260812 06:20:22.853247 31892 master.cc:562] Master@127.31.37.62:41777 shutting down...
I20260812 06:20:22.857555 31892 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:22.857780 31892 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:22.857875 31892 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6f364bb7cefb4748b15634a603a5e490: stopping tablet replica
I20260812 06:20:22.870211 31892 master.cc:584] Master@127.31.37.62:41777 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5688 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:22.975978 31892 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.37.62:42681
I20260812 06:20:22.976468 31892 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.978924 32119 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.978946 32120 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.979029 32122 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:22.978997 31892 server_base.cc:1061] running on GCE node
I20260812 06:20:22.979343 31892 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.979379 31892 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:22.979394 31892 hybrid_clock.cc:648] HybridClock initialized: now 1786515622979394 us; error 0 us; skew 500 ppm
I20260812 06:20:22.980268 31892 webserver.cc:533] Webserver started at http://127.31.37.62:33817/ using document root <none> and password file <none>
I20260812 06:20:22.980463 31892 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.980513 31892 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.980576 31892 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.980926 31892 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/master-0-root/instance:
uuid: "6460da813a4a4103b28cdd7349e40867"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-1zqn"
I20260812 06:20:22.982389 31892 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:22.983362 32130 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.983698 31892 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.983771 31892 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/master-0-root
uuid: "6460da813a4a4103b28cdd7349e40867"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-1zqn"
I20260812 06:20:22.983871 31892 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:23.020416 31892 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:23.020946 31892 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:23.025818 31892 rpc_server.cc:307] RPC server started. Bound to: 127.31.37.62:42681
I20260812 06:20:23.029314 32194 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:23.032227 32193 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.37.62:42681 every 8 connection(s)
I20260812 06:20:23.034509 32194 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867: Bootstrap starting.
I20260812 06:20:23.035386 32194 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:23.036566 32194 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867: No bootstrap required, opened a new log
I20260812 06:20:23.036988 32194 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER }
I20260812 06:20:23.037072 32194 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:23.037098 32194 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6460da813a4a4103b28cdd7349e40867, State: Initialized, Role: FOLLOWER
I20260812 06:20:23.037294 32194 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [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: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER }
I20260812 06:20:23.037364 32194 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:23.037387 32194 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:23.037416 32194 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:23.038147 32194 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER }
I20260812 06:20:23.038286 32194 leader_election.cc:304] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [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: 6460da813a4a4103b28cdd7349e40867; no voters: 
I20260812 06:20:23.038497 32194 leader_election.cc:290] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:23.038729 32197 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:23.038956 32197 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 1 LEADER]: Becoming Leader. State: Replica: 6460da813a4a4103b28cdd7349e40867, State: Running, Role: LEADER
I20260812 06:20:23.039014 32194 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:23.039127 32197 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [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: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER }
I20260812 06:20:23.039649 32199 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6460da813a4a4103b28cdd7349e40867. Latest consensus state: current_term: 1 leader_uuid: "6460da813a4a4103b28cdd7349e40867" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER } }
I20260812 06:20:23.039621 32198 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6460da813a4a4103b28cdd7349e40867" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6460da813a4a4103b28cdd7349e40867" member_type: VOTER } }
I20260812 06:20:23.039738 32199 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:23.039752 32198 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:23.040398 32206 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:23.041128 32206 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:23.041373 31892 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:23.043128 32206 catalog_manager.cc:1383] Generated new cluster ID: dc8d89251b12408abec047836176f996
I20260812 06:20:23.043195 32206 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:23.059207 32206 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:23.059782 32206 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:23.071184 32206 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867: Generated new TSK 0
I20260812 06:20:23.071383 32206 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:23.073899 31892 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:23.076053 32222 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:23.076028 32219 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:23.076025 32218 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:23.076254 31892 server_base.cc:1061] running on GCE node
I20260812 06:20:23.076479 31892 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:23.076521 31892 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:23.076536 31892 hybrid_clock.cc:648] HybridClock initialized: now 1786515623076537 us; error 0 us; skew 500 ppm
I20260812 06:20:23.077389 31892 webserver.cc:533] Webserver started at http://127.31.37.1:38765/ using document root <none> and password file <none>
I20260812 06:20:23.077531 31892 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:23.077576 31892 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:23.077631 31892 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:23.077977 31892 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/instance:
uuid: "9aa9014890264681add478a47e5c2519"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-1zqn"
I20260812 06:20:23.079454 31892 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:23.080370 32228 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:23.080598 31892 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:23.080662 31892 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root
uuid: "9aa9014890264681add478a47e5c2519"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-1zqn"
I20260812 06:20:23.080724 31892 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:23.085397 31892 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:23.085695 31892 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:23.085932 31892 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:23.086424 31892 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:23.086463 31892 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:23.086526 31892 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:23.086565 31892 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:23.091145 31892 rpc_server.cc:307] RPC server started. Bound to: 127.31.37.1:46389
I20260812 06:20:23.091971 32305 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.37.1:46389 every 8 connection(s)
I20260812 06:20:23.103478 32306 heartbeater.cc:344] Connected to a master server at 127.31.37.62:42681
I20260812 06:20:23.103616 32306 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:23.103842 32306 heartbeater.cc:507] Master 127.31.37.62:42681 requested a full tablet report, sending...
I20260812 06:20:23.104566 32152 ts_manager.cc:194] Registered new tserver with Master: 9aa9014890264681add478a47e5c2519 (127.31.37.1:46389)
I20260812 06:20:23.104671 31892 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012541557s
I20260812 06:20:23.105423 32152 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33206
I20260812 06:20:23.112380 32152 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33218:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:23.121140 32260 tablet_service.cc:1511] Processing CreateTablet for tablet 539a6b0db2634c1daad5ba00e085370d (DEFAULT_TABLE table=heavy-update-compaction-test [id=254536a7d75c47c3af26df41770c7512]), partition=
I20260812 06:20:23.121390 32260 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 539a6b0db2634c1daad5ba00e085370d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:23.123289 32319 tablet_bootstrap.cc:492] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Bootstrap starting.
I20260812 06:20:23.124258 32319 tablet_bootstrap.cc:654] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:23.125308 32319 tablet_bootstrap.cc:492] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: No bootstrap required, opened a new log
I20260812 06:20:23.125380 32319 ts_tablet_manager.cc:1403] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:23.125721 32319 raft_consensus.cc:359] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9aa9014890264681add478a47e5c2519" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 46389 } }
I20260812 06:20:23.125805 32319 raft_consensus.cc:385] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:23.125828 32319 raft_consensus.cc:740] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9aa9014890264681add478a47e5c2519, State: Initialized, Role: FOLLOWER
I20260812 06:20:23.125922 32319 consensus_queue.cc:260] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [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: "9aa9014890264681add478a47e5c2519" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 46389 } }
I20260812 06:20:23.125988 32319 raft_consensus.cc:399] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:23.126010 32319 raft_consensus.cc:493] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:23.126039 32319 raft_consensus.cc:3060] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:23.126914 32319 raft_consensus.cc:515] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9aa9014890264681add478a47e5c2519" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 46389 } }
I20260812 06:20:23.127044 32319 leader_election.cc:304] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [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: 9aa9014890264681add478a47e5c2519; no voters: 
I20260812 06:20:23.127203 32319 leader_election.cc:290] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:23.127342 32321 raft_consensus.cc:2804] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:23.127584 32321 raft_consensus.cc:697] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 1 LEADER]: Becoming Leader. State: Replica: 9aa9014890264681add478a47e5c2519, State: Running, Role: LEADER
I20260812 06:20:23.127632 32306 heartbeater.cc:499] Master 127.31.37.62:42681 was elected leader, sending a full tablet report...
I20260812 06:20:23.127669 32319 ts_tablet_manager.cc:1434] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:23.127789 32321 consensus_queue.cc:237] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [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: "9aa9014890264681add478a47e5c2519" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 46389 } }
I20260812 06:20:23.129103 32152 catalog_manager.cc:5719] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9aa9014890264681add478a47e5c2519 (127.31.37.1). New cstate: current_term: 1 leader_uuid: "9aa9014890264681add478a47e5c2519" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9aa9014890264681add478a47e5c2519" member_type: VOTER last_known_addr { host: "127.31.37.1" port: 46389 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:23.191617 31892 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.010s
I20260812 06:20:23.342674 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushMRSOp(539a6b0db2634c1daad5ba00e085370d): perf score=19.054940
I20260812 06:20:23.504329 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushMRSOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.161s	user 0.114s	sys 0.047s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":867,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42068,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:23.505118 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling LogGCOp(539a6b0db2634c1daad5ba00e085370d): free 20743880 bytes of WAL
I20260812 06:20:23.505441 32234 log_reader.cc:385] T 539a6b0db2634c1daad5ba00e085370d: removed 2 log segments from log reader
I20260812 06:20:23.505515 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000001 (ops 1-6)
I20260812 06:20:23.505568 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000002 (ops 7-11)
I20260812 06:20:23.511070 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: LogGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:23.511488 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d): 16411396 bytes on disk
I20260812 06:20:23.512032 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.512595 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:23.526068 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.526602 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:23.680416 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.154s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":981,"lbm_read_time_us":10024,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24353,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":407,"threads_started":5,"update_count":2000}
I20260812 06:20:23.681126 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:23.747409 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.066s	user 0.048s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26211,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.747979 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:23.758733 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.759177 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:23.942613 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.183s	user 0.126s	sys 0.053s 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":227,"lbm_read_time_us":13286,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30029,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:20:23.943434 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=11.118625
I20260812 06:20:23.989063 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.045s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18361,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:23.989638 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:24.013059 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.023s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.013893 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:24.031409 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.032366 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:24.209021 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.176s	user 0.123s	sys 0.052s 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":834,"lbm_read_time_us":12780,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28973,"lbm_writes_lt_1ms":543,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:20:24.209709 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:24.266819 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.057s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.267433 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:24.294883 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.027s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.295390 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:24.482234 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.187s	user 0.133s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":12629,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31738,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:20:24.482857 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:24.544166 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.061s	user 0.014s	sys 0.040s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":27646,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.544739 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=3.181125
I20260812 06:20:24.572788 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.028s	user 0.014s	sys 0.013s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7085,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:24.573329 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:24.583420 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.583899 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:24.807861 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.224s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1626,"lbm_read_time_us":14522,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37125,"lbm_writes_lt_1ms":643,"mutex_wait_us":329,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":54016,"update_count":3000}
I20260812 06:20:24.808635 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:24.875056 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.066s	user 0.049s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.875712 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:24.892611 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.893244 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushMRSOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:24.929316 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushMRSOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":317,"dirs.run_wall_time_us":1604,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1720,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:24.929965 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:25.116376 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.186s	user 0.139s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":59,"lbm_read_time_us":10902,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33745,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:20:25.117144 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling LogGCOp(539a6b0db2634c1daad5ba00e085370d): free 124257242 bytes of WAL
I20260812 06:20:25.117686 32234 log_reader.cc:385] T 539a6b0db2634c1daad5ba00e085370d: removed 12 log segments from log reader
I20260812 06:20:25.117750 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000003 (ops 12-16)
I20260812 06:20:25.117797 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000004 (ops 17-21)
I20260812 06:20:25.117874 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000005 (ops 22-26)
I20260812 06:20:25.117919 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000006 (ops 27-31)
I20260812 06:20:25.117957 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000007 (ops 32-36)
I20260812 06:20:25.118029 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000008 (ops 37-41)
I20260812 06:20:25.118078 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000009 (ops 42-46)
I20260812 06:20:25.118113 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000010 (ops 47-51)
I20260812 06:20:25.118153 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000011 (ops 52-56)
I20260812 06:20:25.118196 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000012 (ops 57-61)
I20260812 06:20:25.118238 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000013 (ops 62-66)
I20260812 06:20:25.118280 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000014 (ops 67-70)
I20260812 06:20:25.149219 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: LogGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:25.149859 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=17.071750
I20260812 06:20:25.215654 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.066s	user 0.038s	sys 0.023s Metrics: {"bytes_written":19609787,"delete_count":0,"lbm_write_time_us":24338,"lbm_writes_lt_1ms":481,"mutex_wait_us":201,"reinsert_count":0,"update_count":2390}
I20260812 06:20:25.216391 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d): 472 bytes on disk
I20260812 06:20:25.216876 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.217314 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=3.181125
I20260812 06:20:25.230012 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":5005192,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:20:25.230491 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:25.427807 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.197s	user 0.152s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1329,"lbm_read_time_us":14530,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33309,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":3000}
I20260812 06:20:25.428565 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:25.490145 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.061s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22190,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.490738 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:25.501932 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.502447 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:25.695508 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.193s	user 0.139s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":905,"lbm_read_time_us":13245,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32781,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:20:25.696167 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=11.118625
I20260812 06:20:25.736663 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.040s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":16886,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.737720 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:25.757961 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.020s	user 0.003s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5010,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.758492 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:25.926563 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.168s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":11839,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27293,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.927155 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=11.118625
I20260812 06:20:25.970942 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.044s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20064,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.971483 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:25.992326 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3829,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:20:25.992817 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:26.003706 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.004271 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:26.156868 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.152s	user 0.124s	sys 0.029s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":12176,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29000,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:20:26.157665 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:26.190580 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.033s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13935,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.191192 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:26.204773 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.205381 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:26.341377 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.136s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":9610,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26870,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:20:26.342175 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:26.382097 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.040s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16413,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.382635 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushMRSOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:26.423897 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushMRSOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.041s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1562,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2108,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:26.424585 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d): 447 bytes on disk
I20260812 06:20:26.425005 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.425470 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=3.181125
I20260812 06:20:26.437361 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:26.437917 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling LogGCOp(539a6b0db2634c1daad5ba00e085370d): free 112239324 bytes of WAL
I20260812 06:20:26.438247 32234 log_reader.cc:385] T 539a6b0db2634c1daad5ba00e085370d: removed 11 log segments from log reader
I20260812 06:20:26.438323 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000015 (ops 71-75)
I20260812 06:20:26.438378 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000016 (ops 76-80)
I20260812 06:20:26.438463 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000017 (ops 81-85)
I20260812 06:20:26.438510 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000018 (ops 86-90)
I20260812 06:20:26.438547 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000019 (ops 91-95)
I20260812 06:20:26.438587 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000020 (ops 96-100)
I20260812 06:20:26.438648 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000021 (ops 101-105)
I20260812 06:20:26.438686 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000022 (ops 106-110)
I20260812 06:20:26.438727 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000023 (ops 111-115)
I20260812 06:20:26.438768 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000024 (ops 116-120)
I20260812 06:20:26.438808 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000025 (ops 121-124)
I20260812 06:20:26.463596 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: LogGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:26.464156 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:26.479270 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.479730 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:26.490190 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.490665 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:26.677726 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.187s	user 0.143s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":710,"lbm_read_time_us":14066,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37717,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:20:26.680521 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:26.729493 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.049s	user 0.035s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.729971 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:26.745798 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.746373 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:26.918601 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.172s	user 0.128s	sys 0.041s 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":1006,"lbm_read_time_us":10648,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33604,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:26.919371 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=12.110812
I20260812 06:20:26.951794 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.032s	user 0.018s	sys 0.011s Metrics: {"bytes_written":13784349,"delete_count":0,"lbm_write_time_us":14466,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:20:26.952423 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.196750
I20260812 06:20:26.965095 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.012s	user 0.002s	sys 0.010s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:20:26.965580 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.106024 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.140s	user 0.095s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672231,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":60,"lbm_read_time_us":9694,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24111,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:20:27.107123 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:27.146384 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.039s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17469,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.146881 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:27.160784 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.161324 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.299880 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.138s	user 0.094s	sys 0.038s 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":546,"lbm_read_time_us":7939,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26397,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35584,"update_count":2000}
I20260812 06:20:27.300674 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:27.350804 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.050s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17271,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":1500}
I20260812 06:20:27.351382 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:27.363947 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.364564 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.501956 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.137s	user 0.103s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":9353,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27253,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2000}
I20260812 06:20:27.502816 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:27.540330 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.037s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.540942 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:27.557338 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.558195 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.692517 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.134s	user 0.121s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":431,"lbm_read_time_us":9117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27411,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:27.693145 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:27.749977 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.057s	user 0.028s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19161,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.750581 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:27.761498 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.762008 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.910283 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.148s	user 0.085s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":10897,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23588,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:20:27.914760 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=10.126437
I20260812 06:20:27.947285 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.032s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12430563,"delete_count":0,"lbm_write_time_us":13403,"lbm_writes_lt_1ms":306,"mutex_wait_us":630,"reinsert_count":0,"update_count":1515}
I20260812 06:20:27.948166 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:27.960840 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:20:27.961297 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushMRSOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:27.991997 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushMRSOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1510,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:27.992660 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling LogGCOp(539a6b0db2634c1daad5ba00e085370d): free 129773824 bytes of WAL
I20260812 06:20:27.992893 32234 log_reader.cc:385] T 539a6b0db2634c1daad5ba00e085370d: removed 13 log segments from log reader
I20260812 06:20:27.992938 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000026 (ops 125-129)
I20260812 06:20:27.992966 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000027 (ops 130-134)
I20260812 06:20:27.993031 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000028 (ops 135-139)
I20260812 06:20:27.993074 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000029 (ops 140-144)
I20260812 06:20:27.993115 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000030 (ops 145-148)
I20260812 06:20:27.993178 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000031 (ops 149-153)
I20260812 06:20:27.993218 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000032 (ops 154-158)
I20260812 06:20:27.993258 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000033 (ops 159-163)
I20260812 06:20:27.993297 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000034 (ops 164-168)
I20260812 06:20:27.993335 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000035 (ops 169-173)
I20260812 06:20:27.993378 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000036 (ops 174-178)
I20260812 06:20:27.993423 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000037 (ops 179-183)
I20260812 06:20:27.993462 32234 log.cc:1079] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: Deleting log segment in path: /tmp/dist-test-taskOOJPPP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515617262856-31892-0/minicluster-data/ts-0-root/wals/539a6b0db2634c1daad5ba00e085370d/wal-000000038 (ops 184-188)
I20260812 06:20:28.025312 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: LogGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.032s	user 0.004s	sys 0.027s Metrics: {}
I20260812 06:20:28.026250 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d): 483 bytes on disk
I20260812 06:20:28.026821 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: UndoDeltaBlockGCOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.027415 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=4.173312
I20260812 06:20:28.055888 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.028s	user 0.009s	sys 0.015s Metrics: {"bytes_written":5825681,"delete_count":0,"lbm_write_time_us":7414,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:20:28.056450 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.196750
I20260812 06:20:28.063959 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.007s	user 0.005s	sys 0.001s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":2436,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:20:28.064483 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:28.270416 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.206s	user 0.141s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877298,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":297,"lbm_read_time_us":14894,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34562,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:20:28.271149 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=14.095187
I20260812 06:20:28.314320 31892 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.123s	user 1.889s	sys 0.174s
I20260812 06:20:28.327723 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.056s	user 0.037s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19720,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.328343 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d): perf score=2.188937
I20260812 06:20:28.338505 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: FlushDeltaMemStoresOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.338945 32308 maintenance_manager.cc:419] P 9aa9014890264681add478a47e5c2519: Scheduling MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d): perf score=1.000000
I20260812 06:20:28.396437 31892 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.002s	sys 0.000s
I20260812 06:20:28.396939 31892 tablet_server.cc:179] TabletServer@127.31.37.1:0 shutting down...
I20260812 06:20:28.478323 32234 maintenance_manager.cc:643] P 9aa9014890264681add478a47e5c2519: MajorDeltaCompactionOp(539a6b0db2634c1daad5ba00e085370d) complete. Timing: real 0.139s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_hit":248,"cfile_cache_hit_bytes":10135085,"cfile_cache_miss":284,"cfile_cache_miss_bytes":14639604,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":7658,"lbm_reads_lt_1ms":316,"lbm_write_time_us":26540,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:20:28.479153 31892 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:28.479429 31892 tablet_replica.cc:333] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519: stopping tablet replica
I20260812 06:20:28.479646 31892 raft_consensus.cc:2243] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.479839 31892 raft_consensus.cc:2272] T 539a6b0db2634c1daad5ba00e085370d P 9aa9014890264681add478a47e5c2519 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.495016 31892 tablet_server.cc:196] TabletServer@127.31.37.1:0 shutdown complete.
I20260812 06:20:28.525002 31892 master.cc:562] Master@127.31.37.62:42681 shutting down...
I20260812 06:20:28.528776 31892 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.529001 31892 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.529120 31892 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6460da813a4a4103b28cdd7349e40867: stopping tablet replica
I20260812 06:20:28.541857 31892 master.cc:584] Master@127.31.37.62:42681 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5682 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11372 ms total)

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