[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:22.739660 19678 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.55.190:36923
I20260812 06:16:22.740754 19678 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:22.741472 19678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.748095 19683 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.748153 19686 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.748358 19678 server_base.cc:1061] running on GCE node
W20260812 06:16:22.748458 19684 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.749033 19678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.749168 19678 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.749219 19678 hybrid_clock.cc:648] HybridClock initialized: now 1786515382749217 us; error 0 us; skew 500 ppm
I20260812 06:16:22.751189 19678 webserver.cc:533] Webserver started at http://127.19.55.190:33999/ using document root <none> and password file <none>
I20260812 06:16:22.751784 19678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.751924 19678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.752231 19678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.754179 19678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/master-0-root/instance:
uuid: "a1e0072a4f6a43f084ef3e7867460d87"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-njxd"
I20260812 06:16:22.758096 19678 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:22.760440 19691 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.761647 19678 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:22.761794 19678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/master-0-root
uuid: "a1e0072a4f6a43f084ef3e7867460d87"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-njxd"
I20260812 06:16:22.761906 19678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.788087 19678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.788849 19678 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:22.789055 19678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.797545 19752 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.55.190:36923 every 8 connection(s)
I20260812 06:16:22.797540 19678 rpc_server.cc:307] RPC server started. Bound to: 127.19.55.190:36923
I20260812 06:16:22.799986 19753 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:22.805888 19753 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: Bootstrap starting.
I20260812 06:16:22.808521 19753 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:22.809648 19753 log.cc:826] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:22.811620 19753 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: No bootstrap required, opened a new log
I20260812 06:16:22.814778 19753 raft_consensus.cc:359] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER }
I20260812 06:16:22.814985 19753 raft_consensus.cc:385] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:22.815064 19753 raft_consensus.cc:740] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a1e0072a4f6a43f084ef3e7867460d87, State: Initialized, Role: FOLLOWER
I20260812 06:16:22.815742 19753 consensus_queue.cc:260] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [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: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER }
I20260812 06:16:22.815929 19753 raft_consensus.cc:399] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:22.816006 19753 raft_consensus.cc:493] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:22.816192 19753 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:22.817149 19753 raft_consensus.cc:515] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER }
I20260812 06:16:22.817735 19753 leader_election.cc:304] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [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: a1e0072a4f6a43f084ef3e7867460d87; no voters: 
I20260812 06:16:22.818131 19753 leader_election.cc:290] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:22.818287 19758 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:22.818585 19758 raft_consensus.cc:697] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 1 LEADER]: Becoming Leader. State: Replica: a1e0072a4f6a43f084ef3e7867460d87, State: Running, Role: LEADER
I20260812 06:16:22.819121 19758 consensus_queue.cc:237] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [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: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER }
I20260812 06:16:22.819259 19753 sys_catalog.cc:565] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:22.821336 19760 sys_catalog.cc:455] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a1e0072a4f6a43f084ef3e7867460d87. Latest consensus state: current_term: 1 leader_uuid: "a1e0072a4f6a43f084ef3e7867460d87" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER } }
I20260812 06:16:22.821379 19759 sys_catalog.cc:455] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a1e0072a4f6a43f084ef3e7867460d87" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1e0072a4f6a43f084ef3e7867460d87" member_type: VOTER } }
I20260812 06:16:22.821489 19759 sys_catalog.cc:458] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.821491 19760 sys_catalog.cc:458] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:22.821936 19678 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:22.823948 19773 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:22.824023 19773 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:22.824110 19772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:22.824875 19772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:22.830425 19772 catalog_manager.cc:1383] Generated new cluster ID: f0d3a16325ad4e8c956e99a12e4e596c
I20260812 06:16:22.830520 19772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:22.847523 19772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:22.848474 19772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:22.856901 19772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: Generated new TSK 0
I20260812 06:16:22.857707 19772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:22.887133 19678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:22.890473 19780 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:22.890502 19778 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.890755 19678 server_base.cc:1061] running on GCE node
W20260812 06:16:22.890857 19782 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:22.891106 19678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:22.891170 19678 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:22.891208 19678 hybrid_clock.cc:648] HybridClock initialized: now 1786515382891208 us; error 0 us; skew 500 ppm
I20260812 06:16:22.892212 19678 webserver.cc:533] Webserver started at http://127.19.55.129:37717/ using document root <none> and password file <none>
I20260812 06:16:22.892396 19678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:22.892470 19678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:22.892555 19678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:22.892976 19678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/instance:
uuid: "62c7f61ed2914ea3abe591b7eaa79560"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-njxd"
I20260812 06:16:22.894771 19678 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:22.896138 19788 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.896421 19678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:22.896504 19678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root
uuid: "62c7f61ed2914ea3abe591b7eaa79560"
format_stamp: "Formatted at 2026-08-12 06:16:22 on dist-test-slave-njxd"
I20260812 06:16:22.896606 19678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:22.929913 19678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:22.930418 19678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:22.930986 19678 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:22.932005 19678 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:22.932070 19678 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.932142 19678 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:22.932181 19678 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:22.947853 19678 rpc_server.cc:307] RPC server started. Bound to: 127.19.55.129:35153
I20260812 06:16:22.947948 19861 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.55.129:35153 every 8 connection(s)
I20260812 06:16:22.966138 19862 heartbeater.cc:344] Connected to a master server at 127.19.55.190:36923
I20260812 06:16:22.966491 19862 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:22.967347 19862 heartbeater.cc:507] Master 127.19.55.190:36923 requested a full tablet report, sending...
I20260812 06:16:22.969543 19710 ts_manager.cc:194] Registered new tserver with Master: 62c7f61ed2914ea3abe591b7eaa79560 (127.19.55.129:35153)
I20260812 06:16:22.970207 19678 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.021501743s
I20260812 06:16:22.971539 19710 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59656
I20260812 06:16:22.983778 19710 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59662:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:23.001936 19821 tablet_service.cc:1511] Processing CreateTablet for tablet 1e87564f3e614e30b0c4624a34afcdd5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cf3bb9730e3f4366a78a4ef9588f7290]), partition=
I20260812 06:16:23.002511 19821 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1e87564f3e614e30b0c4624a34afcdd5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:23.005404 19880 tablet_bootstrap.cc:492] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Bootstrap starting.
I20260812 06:16:23.006587 19880 tablet_bootstrap.cc:654] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:23.007881 19880 tablet_bootstrap.cc:492] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: No bootstrap required, opened a new log
I20260812 06:16:23.007983 19880 ts_tablet_manager.cc:1403] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:23.008531 19880 raft_consensus.cc:359] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62c7f61ed2914ea3abe591b7eaa79560" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 35153 } }
I20260812 06:16:23.008641 19880 raft_consensus.cc:385] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:23.008665 19880 raft_consensus.cc:740] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 62c7f61ed2914ea3abe591b7eaa79560, State: Initialized, Role: FOLLOWER
I20260812 06:16:23.008886 19880 consensus_queue.cc:260] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [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: "62c7f61ed2914ea3abe591b7eaa79560" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 35153 } }
I20260812 06:16:23.008965 19880 raft_consensus.cc:399] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:23.008991 19880 raft_consensus.cc:493] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:23.009073 19880 raft_consensus.cc:3060] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:23.010314 19880 raft_consensus.cc:515] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62c7f61ed2914ea3abe591b7eaa79560" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 35153 } }
I20260812 06:16:23.010443 19880 leader_election.cc:304] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [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: 62c7f61ed2914ea3abe591b7eaa79560; no voters: 
I20260812 06:16:23.010751 19880 leader_election.cc:290] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:23.011214 19883 raft_consensus.cc:2804] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:23.011284 19880 ts_tablet_manager.cc:1434] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:23.011503 19862 heartbeater.cc:499] Master 127.19.55.190:36923 was elected leader, sending a full tablet report...
I20260812 06:16:23.011492 19883 raft_consensus.cc:697] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 1 LEADER]: Becoming Leader. State: Replica: 62c7f61ed2914ea3abe591b7eaa79560, State: Running, Role: LEADER
I20260812 06:16:23.012049 19883 consensus_queue.cc:237] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [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: "62c7f61ed2914ea3abe591b7eaa79560" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 35153 } }
I20260812 06:16:23.015254 19710 catalog_manager.cc:5719] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 reported cstate change: term changed from 0 to 1, leader changed from <none> to 62c7f61ed2914ea3abe591b7eaa79560 (127.19.55.129). New cstate: current_term: 1 leader_uuid: "62c7f61ed2914ea3abe591b7eaa79560" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "62c7f61ed2914ea3abe591b7eaa79560" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 35153 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:23.172518 19678 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.149s	user 0.003s	sys 0.061s
I20260812 06:16:23.199333 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=3.179940
I20260812 06:16:23.323484 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.124s	user 0.072s	sys 0.028s Metrics: {"bytes_written":3692405,"cfile_init":1,"compiler_manager_pool.queue_time_us":275,"delete_count":0,"dirs.queue_time_us":107,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":806,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":25028,"lbm_writes_1-10_ms":7,"lbm_writes_lt_1ms":150,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"thread_start_us":100,"threads_started":1,"update_count":450}
I20260812 06:16:23.324517 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=0.891874
I20260812 06:16:23.415190 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.090s	user 0.062s	sys 0.025s Metrics: {"cfile_cache_miss":121,"cfile_cache_miss_bytes":7831772,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":455,"lbm_read_time_us":2981,"lbm_reads_lt_1ms":153,"lbm_write_time_us":17352,"lbm_writes_lt_1ms":133,"mutex_wait_us":34,"peak_mem_usage":11958878,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":290,"threads_started":5,"update_count":450}
I20260812 06:16:23.417943 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5): 411733 bytes on disk
I20260812 06:16:23.418648 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:23.419301 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=6.157687
I20260812 06:16:23.455780 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.036s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13175,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:23.456418 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:23.600229 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.144s	user 0.078s	sys 0.063s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12344439,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":813,"lbm_read_time_us":4714,"lbm_reads_lt_1ms":263,"lbm_write_time_us":47872,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":240,"mutex_wait_us":44,"peak_mem_usage":25836184,"reinsert_count":0,"update_count":1000}
I20260812 06:16:23.600986 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=7.149875
I20260812 06:16:23.637137 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.036s	user 0.014s	sys 0.018s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":19492,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:23.637792 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:23.677176 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.039s	user 0.010s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":13389,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:23.677816 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:23.690937 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:23.691526 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:23.949875 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.258s	user 0.137s	sys 0.108s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20549491,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1054,"lbm_read_time_us":11813,"lbm_reads_lt_1ms":473,"lbm_write_time_us":80333,"lbm_writes_1-10_ms":9,"lbm_writes_lt_1ms":434,"mutex_wait_us":413,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:23.950773 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=10.126437
I20260812 06:16:24.003962 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.053s	user 0.025s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":28758,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:24.004475 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:24.022385 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.022926 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:24.231941 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.209s	user 0.115s	sys 0.091s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":636,"lbm_read_time_us":7848,"lbm_reads_lt_1ms":472,"lbm_write_time_us":83578,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":439,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:16:24.232630 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=14.095187
I20260812 06:16:24.298563 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.066s	user 0.034s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":36990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:24.299078 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:24.328017 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.029s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.328501 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:24.560209 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.232s	user 0.131s	sys 0.100s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":10347,"lbm_reads_lt_1ms":564,"lbm_write_time_us":99660,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":540,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:16:24.561857 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=15.087375
I20260812 06:16:24.641463 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.079s	user 0.030s	sys 0.042s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":43522,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:24.642047 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=6.157687
I20260812 06:16:24.697809 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.056s	user 0.029s	sys 0.015s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":26490,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:24.698365 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:24.735508 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.037s	user 0.018s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":17434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:24.736035 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:25.085435 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.349s	user 0.177s	sys 0.164s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32856737,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":827,"lbm_read_time_us":14849,"lbm_reads_lt_1ms":765,"lbm_write_time_us":137264,"lbm_writes_1-10_ms":8,"lbm_writes_lt_1ms":735,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":313,"threads_started":5,"update_count":3500}
I20260812 06:16:25.085996 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=18.063937
I20260812 06:16:25.199734 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.114s	user 0.040s	sys 0.063s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":61960,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:25.200312 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=3.181125
I20260812 06:16:25.231272 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":19709,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:25.231973 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:25.265269 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.033s	user 0.008s	sys 0.017s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":17164,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:25.265964 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:25.310997 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.045s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1695,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1644,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:25.311839 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=3.181125
I20260812 06:16:25.338829 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.027s	user 0.008s	sys 0.017s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":16488,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:25.339468 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling LogGCOp(1e87564f3e614e30b0c4624a34afcdd5): free 132983161 bytes of WAL
I20260812 06:16:25.339828 19795 log_reader.cc:385] T 1e87564f3e614e30b0c4624a34afcdd5: removed 13 log segments from log reader
I20260812 06:16:25.339887 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000001 (ops 1-6)
I20260812 06:16:25.339962 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000002 (ops 7-10)
I20260812 06:16:25.340013 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000003 (ops 11-15)
I20260812 06:16:25.340031 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000004 (ops 16-20)
I20260812 06:16:25.340090 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000005 (ops 21-25)
I20260812 06:16:25.340148 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000006 (ops 26-30)
I20260812 06:16:25.340189 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000007 (ops 31-35)
I20260812 06:16:25.340229 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000008 (ops 36-40)
I20260812 06:16:25.340263 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000009 (ops 41-45)
I20260812 06:16:25.340301 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000010 (ops 46-50)
I20260812 06:16:25.340338 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000011 (ops 51-55)
I20260812 06:16:25.340377 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000012 (ops 56-60)
I20260812 06:16:25.340416 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000013 (ops 61-65)
I20260812 06:16:25.372121 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: LogGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.032s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:16:25.372506 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=6.157687
I20260812 06:16:25.400893 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.028s	user 0.019s	sys 0.000s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8949,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:25.401445 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:25.764285 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.363s	user 0.183s	sys 0.173s Metrics: {"cfile_cache_miss":1035,"cfile_cache_miss_bytes":45164207,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":860,"lbm_read_time_us":18095,"lbm_reads_lt_1ms":1067,"lbm_write_time_us":94484,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":1038,"mutex_wait_us":59,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":381,"threads_started":6,"update_count":5000}
I20260812 06:16:25.765141 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=20.048312
I20260812 06:16:25.844273 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.078s	user 0.031s	sys 0.029s Metrics: {"bytes_written":22030202,"delete_count":0,"lbm_write_time_us":28373,"lbm_writes_lt_1ms":540,"reinsert_count":0,"update_count":2685}
I20260812 06:16:25.844851 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=5.165500
I20260812 06:16:25.865149 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.020s	user 0.016s	sys 0.000s Metrics: {"bytes_written":6687192,"delete_count":0,"lbm_write_time_us":7806,"lbm_writes_lt_1ms":166,"reinsert_count":0,"update_count":815}
I20260812 06:16:25.865846 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5): 473 bytes on disk
I20260812 06:16:25.866386 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:16:25.866997 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:26.087353 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.220s	user 0.131s	sys 0.089s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32856621,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1187,"lbm_read_time_us":16233,"lbm_reads_lt_1ms":772,"lbm_write_time_us":40966,"lbm_writes_lt_1ms":743,"mutex_wait_us":384,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3500}
I20260812 06:16:26.088094 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=18.063937
I20260812 06:16:26.155457 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.067s	user 0.047s	sys 0.018s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31868,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:26.156020 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:26.180998 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.181499 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:26.196786 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.197389 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:26.413862 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.216s	user 0.158s	sys 0.057s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32856738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":574,"lbm_read_time_us":15276,"lbm_reads_lt_1ms":773,"lbm_write_time_us":50006,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":3500}
I20260812 06:16:26.414525 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=15.087375
I20260812 06:16:26.491192 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.076s	user 0.043s	sys 0.029s Metrics: {"bytes_written":16697071,"delete_count":0,"lbm_write_time_us":42990,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":408,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2035}
I20260812 06:16:26.491716 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=6.157687
I20260812 06:16:26.517983 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.026s	user 0.010s	sys 0.011s Metrics: {"bytes_written":7917913,"delete_count":0,"lbm_write_time_us":8939,"lbm_writes_lt_1ms":196,"reinsert_count":0,"update_count":965}
I20260812 06:16:26.518586 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:26.743453 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.225s	user 0.128s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754211,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1367,"lbm_read_time_us":11253,"lbm_reads_lt_1ms":664,"lbm_write_time_us":89987,"lbm_writes_lt_1ms":643,"mutex_wait_us":327,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:26.744089 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=18.063937
I20260812 06:16:26.825206 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.081s	user 0.036s	sys 0.037s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":40092,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:26.825858 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=3.181125
I20260812 06:16:26.844478 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8118,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:26.845041 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:26.855556 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:26.856655 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:26.888790 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1664,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2913,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:26.889554 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling LogGCOp(1e87564f3e614e30b0c4624a34afcdd5): free 120553396 bytes of WAL
I20260812 06:16:26.889904 19795 log_reader.cc:385] T 1e87564f3e614e30b0c4624a34afcdd5: removed 12 log segments from log reader
I20260812 06:16:26.890002 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000014 (ops 66-70)
I20260812 06:16:26.890064 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000015 (ops 71-75)
I20260812 06:16:26.890091 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000016 (ops 76-80)
I20260812 06:16:26.890125 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000017 (ops 81-84)
I20260812 06:16:26.890147 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000018 (ops 85-89)
I20260812 06:16:26.890188 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000019 (ops 90-94)
I20260812 06:16:26.890216 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000020 (ops 95-98)
I20260812 06:16:26.890249 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000021 (ops 99-103)
I20260812 06:16:26.890270 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000022 (ops 104-108)
I20260812 06:16:26.890300 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000023 (ops 109-113)
I20260812 06:16:26.890329 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000024 (ops 114-118)
I20260812 06:16:26.890359 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000025 (ops 119-123)
I20260812 06:16:26.920723 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: LogGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:26.921293 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5): 463 bytes on disk
I20260812 06:16:26.921865 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.922541 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=3.181125
I20260812 06:16:26.936048 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5492,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:16:26.936582 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.196750
I20260812 06:16:26.946851 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3004,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:16:26.947566 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:27.183846 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.236s	user 0.171s	sys 0.064s Metrics: {"cfile_cache_miss":935,"cfile_cache_miss_bytes":41061769,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":442,"lbm_read_time_us":17079,"lbm_reads_lt_1ms":975,"lbm_write_time_us":52484,"lbm_writes_lt_1ms":943,"mutex_wait_us":27,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":80,"threads_started":1,"update_count":4500}
I20260812 06:16:27.184520 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=18.063937
I20260812 06:16:27.258980 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.074s	user 0.038s	sys 0.035s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27313,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:27.259833 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:27.278903 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.279372 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:27.497140 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.218s	user 0.131s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754208,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":13509,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38849,"lbm_writes_lt_1ms":643,"mutex_wait_us":283,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:16:27.497776 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=15.087375
I20260812 06:16:27.553020 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.055s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23343,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:27.553727 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:27.566507 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.566983 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:27.760974 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.194s	user 0.121s	sys 0.071s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25062034,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":11119,"lbm_reads_lt_1ms":574,"lbm_write_time_us":47528,"lbm_writes_lt_1ms":553,"mutex_wait_us":23,"peak_mem_usage":63526250,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2550}
I20260812 06:16:27.761713 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=14.095187
I20260812 06:16:27.836748 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.075s	user 0.020s	sys 0.051s Metrics: {"bytes_written":15999662,"delete_count":0,"lbm_write_time_us":40056,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:16:27.837466 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=5.165500
I20260812 06:16:27.853724 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":6400017,"delete_count":0,"lbm_write_time_us":6419,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:16:27.854315 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:27.860646 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":1903,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:16:27.861441 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:28.144464 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.283s	user 0.143s	sys 0.136s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28344031,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":715,"lbm_read_time_us":15159,"lbm_reads_lt_1ms":663,"lbm_write_time_us":81173,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":629,"mutex_wait_us":31,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":137984,"update_count":2950}
I20260812 06:16:28.145243 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=16.079562
I20260812 06:16:28.216526 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.071s	user 0.039s	sys 0.016s Metrics: {"bytes_written":18091910,"delete_count":0,"lbm_write_time_us":25136,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2205}
I20260812 06:16:28.217053 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=5.165500
I20260812 06:16:28.241725 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.024s	user 0.013s	sys 0.007s Metrics: {"bytes_written":6523096,"delete_count":0,"lbm_write_time_us":8476,"lbm_writes_lt_1ms":162,"reinsert_count":0,"update_count":795}
I20260812 06:16:28.242199 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:28.553951 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.312s	user 0.151s	sys 0.146s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754233,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":526,"lbm_read_time_us":13118,"lbm_reads_lt_1ms":664,"lbm_write_time_us":113002,"lbm_writes_1-10_ms":6,"lbm_writes_lt_1ms":637,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":3000}
I20260812 06:16:28.554864 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=22.032687
I20260812 06:16:28.620237 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.065s	user 0.043s	sys 0.020s Metrics: {"bytes_written":24614720,"delete_count":0,"lbm_write_time_us":30003,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:16:28.620783 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=2.188937
I20260812 06:16:28.634979 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5594,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.635509 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:28.670311 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushMRSOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316414,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1751,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1752,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:28.671813 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling LogGCOp(1e87564f3e614e30b0c4624a34afcdd5): free 124710562 bytes of WAL
I20260812 06:16:28.672116 19795 log_reader.cc:385] T 1e87564f3e614e30b0c4624a34afcdd5: removed 12 log segments from log reader
I20260812 06:16:28.672187 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000026 (ops 124-128)
I20260812 06:16:28.672273 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000027 (ops 129-133)
I20260812 06:16:28.672317 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000028 (ops 134-138)
I20260812 06:16:28.672360 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000029 (ops 139-143)
I20260812 06:16:28.672403 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000030 (ops 144-148)
I20260812 06:16:28.672446 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000031 (ops 149-153)
I20260812 06:16:28.672488 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000032 (ops 154-158)
I20260812 06:16:28.672530 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000033 (ops 159-163)
I20260812 06:16:28.672580 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000034 (ops 164-168)
I20260812 06:16:28.672648 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000035 (ops 169-173)
I20260812 06:16:28.672688 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000036 (ops 174-178)
I20260812 06:16:28.672734 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000037 (ops 179-183)
I20260812 06:16:28.702365 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: LogGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.030s	user 0.004s	sys 0.026s Metrics: {}
I20260812 06:16:28.702988 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=5.165500
I20260812 06:16:28.723665 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.020s	user 0.008s	sys 0.010s Metrics: {"bytes_written":6646162,"delete_count":0,"lbm_write_time_us":8196,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:16:28.724303 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling LogGCOp(1e87564f3e614e30b0c4624a34afcdd5): free 12018006 bytes of WAL
I20260812 06:16:28.724718 19795 log_reader.cc:385] T 1e87564f3e614e30b0c4624a34afcdd5: removed 1 log segments from log reader
I20260812 06:16:28.724821 19795 log.cc:1079] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/1e87564f3e614e30b0c4624a34afcdd5/wal-000000038 (ops 184-188)
I20260812 06:16:28.728014 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: LogGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:28.728494 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:28.735235 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {"bytes_written":1559102,"delete_count":0,"lbm_write_time_us":1783,"lbm_writes_lt_1ms":41,"reinsert_count":0,"update_count":190}
I20260812 06:16:28.735762 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5): 491 bytes on disk
I20260812 06:16:28.736415 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: UndoDeltaBlockGCOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.737061 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=1.000000
I20260812 06:16:29.015568 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: MajorDeltaCompactionOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.278s	user 0.185s	sys 0.086s Metrics: {"cfile_cache_miss":934,"cfile_cache_miss_bytes":41061615,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":949,"lbm_read_time_us":17461,"lbm_reads_lt_1ms":974,"lbm_write_time_us":61063,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":940,"peak_mem_usage":112822188,"reinsert_count":0,"thread_start_us":79,"threads_started":1,"update_count":4500}
I20260812 06:16:29.016909 19863 maintenance_manager.cc:419] P 62c7f61ed2914ea3abe591b7eaa79560: Scheduling FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5): perf score=19.056125
I20260812 06:16:29.029021 19678 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.856s	user 1.871s	sys 0.148s
I20260812 06:16:29.065500 19678 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.003s	sys 0.000s
I20260812 06:16:29.066674 19678 tablet_server.cc:179] TabletServer@127.19.55.129:0 shutting down...
I20260812 06:16:29.116410 19795 maintenance_manager.cc:643] P 62c7f61ed2914ea3abe591b7eaa79560: FlushDeltaMemStoresOp(1e87564f3e614e30b0c4624a34afcdd5) complete. Timing: real 0.099s	user 0.026s	sys 0.070s Metrics: {"bytes_written":20922554,"delete_count":0,"lbm_write_time_us":52712,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:16:29.117398 19678 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:29.117903 19678 tablet_replica.cc:333] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560: stopping tablet replica
I20260812 06:16:29.118168 19678 raft_consensus.cc:2243] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.118417 19678 raft_consensus.cc:2272] T 1e87564f3e614e30b0c4624a34afcdd5 P 62c7f61ed2914ea3abe591b7eaa79560 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.134716 19678 tablet_server.cc:196] TabletServer@127.19.55.129:0 shutdown complete.
I20260812 06:16:29.139693 19678 master.cc:562] Master@127.19.55.190:36923 shutting down...
I20260812 06:16:29.144207 19678 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:29.144431 19678 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:29.144538 19678 tablet_replica.cc:333] T 00000000000000000000000000000000 P a1e0072a4f6a43f084ef3e7867460d87: stopping tablet replica
I20260812 06:16:29.157164 19678 master.cc:584] Master@127.19.55.190:36923 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6507 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:29.246105 19678 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.55.190:37925
I20260812 06:16:29.246466 19678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.248888 19916 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:29.249003 19914 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:29.248999 19918 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:29.249037 19678 server_base.cc:1061] running on GCE node
I20260812 06:16:29.249331 19678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.249373 19678 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:29.249388 19678 hybrid_clock.cc:648] HybridClock initialized: now 1786515389249389 us; error 0 us; skew 500 ppm
I20260812 06:16:29.250406 19678 webserver.cc:533] Webserver started at http://127.19.55.190:41467/ using document root <none> and password file <none>
I20260812 06:16:29.250607 19678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.250697 19678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.250784 19678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.251207 19678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/master-0-root/instance:
uuid: "6f605600599c44b6ad06f30888a10c2c"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-njxd"
I20260812 06:16:29.252872 19678 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:29.253984 19923 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.254274 19678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.254360 19678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/master-0-root
uuid: "6f605600599c44b6ad06f30888a10c2c"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-njxd"
I20260812 06:16:29.254426 19678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:29.263363 19678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.263801 19678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.268211 19678 rpc_server.cc:307] RPC server started. Bound to: 127.19.55.190:37925
I20260812 06:16:29.275985 19979 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.55.190:37925 every 8 connection(s)
I20260812 06:16:29.276544 19981 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.278465 19981 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c: Bootstrap starting.
I20260812 06:16:29.279254 19981 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.280314 19981 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c: No bootstrap required, opened a new log
I20260812 06:16:29.280710 19981 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER }
I20260812 06:16:29.280802 19981 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.280824 19981 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6f605600599c44b6ad06f30888a10c2c, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.280983 19981 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [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: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER }
I20260812 06:16:29.281081 19981 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.281108 19981 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.281149 19981 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.281901 19981 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER }
I20260812 06:16:29.282025 19981 leader_election.cc:304] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [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: 6f605600599c44b6ad06f30888a10c2c; no voters: 
I20260812 06:16:29.282196 19981 leader_election.cc:290] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.282384 19984 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.282598 19984 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 1 LEADER]: Becoming Leader. State: Replica: 6f605600599c44b6ad06f30888a10c2c, State: Running, Role: LEADER
I20260812 06:16:29.282809 19981 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:29.282747 19984 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [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: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER }
I20260812 06:16:29.283320 19986 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6f605600599c44b6ad06f30888a10c2c. Latest consensus state: current_term: 1 leader_uuid: "6f605600599c44b6ad06f30888a10c2c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER } }
I20260812 06:16:29.283309 19985 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6f605600599c44b6ad06f30888a10c2c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f605600599c44b6ad06f30888a10c2c" member_type: VOTER } }
I20260812 06:16:29.283429 19986 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.283461 19985 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.283735 19989 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:29.284600 19989 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:29.284897 19678 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:29.286556 19989 catalog_manager.cc:1383] Generated new cluster ID: c82d6ba64ce942ec9745dc9a2ccdde28
I20260812 06:16:29.286633 19989 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:29.307603 19989 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:29.308197 19989 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:29.313366 19989 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c: Generated new TSK 0
I20260812 06:16:29.313557 19989 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:29.317457 19678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.319720 20007 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:29.319701 20004 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:29.319679 20005 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:29.319763 19678 server_base.cc:1061] running on GCE node
I20260812 06:16:29.320138 19678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.320190 19678 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:29.320209 19678 hybrid_clock.cc:648] HybridClock initialized: now 1786515389320208 us; error 0 us; skew 500 ppm
I20260812 06:16:29.321100 19678 webserver.cc:533] Webserver started at http://127.19.55.129:44229/ using document root <none> and password file <none>
I20260812 06:16:29.321242 19678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.321290 19678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.321350 19678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.321848 19678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/instance:
uuid: "108d5cac4fc74362993e8dfe2cba8f19"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-njxd"
I20260812 06:16:29.323450 19678 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:29.324440 20012 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.324693 19678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:29.324792 19678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root
uuid: "108d5cac4fc74362993e8dfe2cba8f19"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-njxd"
I20260812 06:16:29.324887 19678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:29.333526 19678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.333985 19678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.334328 19678 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:29.334864 19678 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:29.334928 19678 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.335012 19678 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:29.335062 19678 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.339637 19678 rpc_server.cc:307] RPC server started. Bound to: 127.19.55.129:44707
I20260812 06:16:29.341157 20087 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.55.129:44707 every 8 connection(s)
I20260812 06:16:29.351133 20088 heartbeater.cc:344] Connected to a master server at 127.19.55.190:37925
I20260812 06:16:29.351262 20088 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:29.351491 20088 heartbeater.cc:507] Master 127.19.55.190:37925 requested a full tablet report, sending...
I20260812 06:16:29.352195 19941 ts_manager.cc:194] Registered new tserver with Master: 108d5cac4fc74362993e8dfe2cba8f19 (127.19.55.129:44707)
I20260812 06:16:29.352859 19678 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012219678s
I20260812 06:16:29.353101 19941 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34620
I20260812 06:16:29.361123 19941 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34626:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:29.370749 20050 tablet_service.cc:1511] Processing CreateTablet for tablet fefbd37359854580956d22d9564a16c9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=881e26cf629647f2af81eb7c977f77e6]), partition=
I20260812 06:16:29.371078 20050 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fefbd37359854580956d22d9564a16c9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.373409 20100 tablet_bootstrap.cc:492] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Bootstrap starting.
I20260812 06:16:29.374452 20100 tablet_bootstrap.cc:654] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.375717 20100 tablet_bootstrap.cc:492] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: No bootstrap required, opened a new log
I20260812 06:16:29.375846 20100 ts_tablet_manager.cc:1403] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:29.376356 20100 raft_consensus.cc:359] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "108d5cac4fc74362993e8dfe2cba8f19" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 44707 } }
I20260812 06:16:29.376490 20100 raft_consensus.cc:385] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.376541 20100 raft_consensus.cc:740] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 108d5cac4fc74362993e8dfe2cba8f19, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.376740 20100 consensus_queue.cc:260] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [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: "108d5cac4fc74362993e8dfe2cba8f19" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 44707 } }
I20260812 06:16:29.376864 20100 raft_consensus.cc:399] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.376916 20100 raft_consensus.cc:493] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.376976 20100 raft_consensus.cc:3060] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.378049 20100 raft_consensus.cc:515] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "108d5cac4fc74362993e8dfe2cba8f19" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 44707 } }
I20260812 06:16:29.378232 20100 leader_election.cc:304] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [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: 108d5cac4fc74362993e8dfe2cba8f19; no voters: 
I20260812 06:16:29.378486 20100 leader_election.cc:290] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.378685 20102 raft_consensus.cc:2804] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.378917 20088 heartbeater.cc:499] Master 127.19.55.190:37925 was elected leader, sending a full tablet report...
I20260812 06:16:29.378898 20100 ts_tablet_manager.cc:1434] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:29.378948 20102 raft_consensus.cc:697] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 1 LEADER]: Becoming Leader. State: Replica: 108d5cac4fc74362993e8dfe2cba8f19, State: Running, Role: LEADER
I20260812 06:16:29.379144 20102 consensus_queue.cc:237] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [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: "108d5cac4fc74362993e8dfe2cba8f19" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 44707 } }
I20260812 06:16:29.380636 19941 catalog_manager.cc:5719] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 reported cstate change: term changed from 0 to 1, leader changed from <none> to 108d5cac4fc74362993e8dfe2cba8f19 (127.19.55.129). New cstate: current_term: 1 leader_uuid: "108d5cac4fc74362993e8dfe2cba8f19" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "108d5cac4fc74362993e8dfe2cba8f19" member_type: VOTER last_known_addr { host: "127.19.55.129" port: 44707 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.443063 19678 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.015s	sys 0.009s
I20260812 06:16:29.591681 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushMRSOp(fefbd37359854580956d22d9564a16c9): perf score=19.054940
I20260812 06:16:29.764104 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushMRSOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.172s	user 0.114s	sys 0.055s Metrics: {"bytes_written":12307493,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":944,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44377,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:29.764878 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling LogGCOp(fefbd37359854580956d22d9564a16c9): free 20743880 bytes of WAL
I20260812 06:16:29.765161 20019 log_reader.cc:385] T fefbd37359854580956d22d9564a16c9: removed 2 log segments from log reader
I20260812 06:16:29.765229 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000001 (ops 1-6)
I20260812 06:16:29.765285 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000002 (ops 7-11)
I20260812 06:16:29.769917 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: LogGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:29.770366 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:29.783207 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.783860 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:29.940171 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.156s	user 0.128s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":617,"lbm_read_time_us":10467,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27769,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":389,"threads_started":5,"update_count":2000}
I20260812 06:16:29.940901 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=10.126437
I20260812 06:16:29.977357 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16342,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.977939 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9): 16411392 bytes on disk
I20260812 06:16:29.978392 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.978806 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:29.993906 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.994382 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:30.169643 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.175s	user 0.099s	sys 0.059s 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":991,"lbm_read_time_us":8971,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28550,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:16:30.170217 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:30.224772 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23951,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.225411 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:30.243221 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.243714 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:30.399058 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.155s	user 0.120s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":9291,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33668,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:16:30.399689 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=11.118625
I20260812 06:16:30.436331 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.036s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15554,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:30.437103 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:30.454659 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5982,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.455235 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:30.591176 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.136s	user 0.111s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":8569,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26849,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:16:30.591974 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=10.126437
I20260812 06:16:30.636974 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.045s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17912,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.637650 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:30.649868 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.650431 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:30.777480 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.127s	user 0.106s	sys 0.021s 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":716,"lbm_read_time_us":7827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24932,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2000}
I20260812 06:16:30.778306 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=10.126437
I20260812 06:16:30.826894 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.048s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17797,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.827483 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:30.838685 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.839303 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:30.997655 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.158s	user 0.115s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":12074,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26199,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":84096,"update_count":2000}
I20260812 06:16:30.998417 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=10.126437
I20260812 06:16:31.038758 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.040s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:16:31.039340 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:31.052325 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.052876 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushMRSOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:31.085510 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushMRSOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":386,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1426,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1781,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:31.086489 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling LogGCOp(fefbd37359854580956d22d9564a16c9): free 120553325 bytes of WAL
I20260812 06:16:31.086843 20019 log_reader.cc:385] T fefbd37359854580956d22d9564a16c9: removed 12 log segments from log reader
I20260812 06:16:31.086901 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000003 (ops 12-16)
I20260812 06:16:31.086957 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000004 (ops 17-21)
I20260812 06:16:31.087001 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000005 (ops 22-26)
I20260812 06:16:31.087052 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000006 (ops 27-31)
I20260812 06:16:31.087095 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000007 (ops 32-36)
I20260812 06:16:31.087138 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000008 (ops 37-41)
I20260812 06:16:31.087195 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000009 (ops 42-46)
I20260812 06:16:31.087245 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000010 (ops 47-50)
I20260812 06:16:31.087291 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000011 (ops 51-55)
I20260812 06:16:31.087334 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000012 (ops 56-60)
I20260812 06:16:31.087381 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000013 (ops 61-64)
I20260812 06:16:31.087424 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000014 (ops 65-69)
I20260812 06:16:31.114447 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: LogGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:31.115015 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9): 463 bytes on disk
I20260812 06:16:31.115660 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.116250 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=3.181125
I20260812 06:16:31.134908 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.019s	user 0.016s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7165,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:31.135401 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:31.156589 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.021s	user 0.003s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.157136 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:31.374385 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.217s	user 0.150s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":730,"lbm_read_time_us":14658,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35825,"lbm_writes_lt_1ms":643,"mutex_wait_us":506,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":126,"threads_started":1,"update_count":3000}
I20260812 06:16:31.375177 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:31.434478 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.059s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20964,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.435118 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:31.446308 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.446935 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:31.641767 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.195s	user 0.113s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1142,"lbm_read_time_us":13775,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32760,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":631,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:16:31.642459 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:31.703594 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.061s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25629,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.704133 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:31.718743 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.719343 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:31.923871 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.204s	user 0.132s	sys 0.065s 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":276,"lbm_read_time_us":11430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31416,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:16:31.924611 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:31.979516 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.055s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.980070 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:31.992636 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.993374 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:32.158000 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.164s	user 0.126s	sys 0.032s 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":195,"lbm_read_time_us":9985,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31922,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2500}
I20260812 06:16:32.158705 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:32.211685 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.053s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20672,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.212373 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:32.224421 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.225046 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:32.389101 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.164s	user 0.118s	sys 0.033s 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":194,"lbm_read_time_us":9130,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33056,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:16:32.389647 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:32.443166 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.053s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21433,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.443755 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:32.456185 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.456842 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:32.625533 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.168s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":10059,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34717,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:16:32.626349 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:32.679733 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.053s	user 0.031s	sys 0.010s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.680445 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:32.692363 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.692920 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushMRSOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:32.726263 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushMRSOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2063,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:32.727025 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling LogGCOp(fefbd37359854580956d22d9564a16c9): free 129320571 bytes of WAL
I20260812 06:16:32.727339 20019 log_reader.cc:385] T fefbd37359854580956d22d9564a16c9: removed 13 log segments from log reader
I20260812 06:16:32.727404 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000015 (ops 70-74)
I20260812 06:16:32.727442 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000016 (ops 75-79)
I20260812 06:16:32.727481 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000017 (ops 80-84)
I20260812 06:16:32.727514 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000018 (ops 85-88)
I20260812 06:16:32.727545 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000019 (ops 89-93)
I20260812 06:16:32.727574 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000020 (ops 94-98)
I20260812 06:16:32.727600 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000021 (ops 99-102)
I20260812 06:16:32.727635 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000022 (ops 103-107)
I20260812 06:16:32.727669 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000023 (ops 108-112)
I20260812 06:16:32.727699 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000024 (ops 113-117)
I20260812 06:16:32.727726 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000025 (ops 118-122)
I20260812 06:16:32.727754 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000026 (ops 123-127)
I20260812 06:16:32.727782 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000027 (ops 128-132)
I20260812 06:16:32.759189 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: LogGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:32.759805 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:32.775817 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.776314 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9): 491 bytes on disk
I20260812 06:16:32.776839 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.777380 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:32.793279 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.793915 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:33.007017 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.213s	user 0.160s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":519,"lbm_read_time_us":15622,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43577,"lbm_writes_lt_1ms":743,"mutex_wait_us":67,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:16:33.008092 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:33.065544 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.057s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":25460,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:33.066200 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:33.081971 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6023,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.082649 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:33.254153 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.171s	user 0.115s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":979,"lbm_read_time_us":10517,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33753,"lbm_writes_lt_1ms":543,"mutex_wait_us":347,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:16:33.254850 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:33.309782 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.055s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21611,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.310292 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:33.321514 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.322491 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:33.504112 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.181s	user 0.113s	sys 0.056s 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":349,"lbm_read_time_us":10722,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28802,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2500}
I20260812 06:16:33.504823 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:33.556465 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.051s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21403,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.557031 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:33.712839 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.156s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":245,"lbm_read_time_us":9381,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25930,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:16:33.713696 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:33.763162 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.049s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21809,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.763700 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:33.776247 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.776965 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:33.971797 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.195s	user 0.141s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":12915,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31715,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:16:33.972594 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:34.057652 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.085s	user 0.029s	sys 0.056s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":46110,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.058403 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:34.074815 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.075387 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:34.285868 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.210s	user 0.103s	sys 0.104s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":741,"lbm_read_time_us":10694,"lbm_reads_lt_1ms":564,"lbm_write_time_us":61687,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":538,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:16:34.286705 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=14.095187
I20260812 06:16:34.357636 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.071s	user 0.030s	sys 0.041s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":41493,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:34.358361 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:34.378068 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.378572 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushMRSOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:34.435184 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushMRSOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.056s	user 0.030s	sys 0.008s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1362,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5843,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":36,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:34.435966 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling LogGCOp(fefbd37359854580956d22d9564a16c9): free 132571533 bytes of WAL
I20260812 06:16:34.436208 20019 log_reader.cc:385] T fefbd37359854580956d22d9564a16c9: removed 13 log segments from log reader
I20260812 06:16:34.436251 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000028 (ops 133-136)
I20260812 06:16:34.436282 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000029 (ops 137-141)
I20260812 06:16:34.436342 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000030 (ops 142-146)
I20260812 06:16:34.436384 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000031 (ops 147-151)
I20260812 06:16:34.436416 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000032 (ops 152-156)
I20260812 06:16:34.436479 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000033 (ops 157-161)
I20260812 06:16:34.436503 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000034 (ops 162-166)
I20260812 06:16:34.436542 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000035 (ops 167-170)
I20260812 06:16:34.436581 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000036 (ops 171-175)
I20260812 06:16:34.436622 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000037 (ops 176-180)
I20260812 06:16:34.436662 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000038 (ops 181-185)
I20260812 06:16:34.436702 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000039 (ops 186-190)
I20260812 06:16:34.436743 20019 log.cc:1079] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: Deleting log segment in path: /tmp/dist-test-taskwNI3zN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515382728146-19678-0/minicluster-data/ts-0-root/wals/fefbd37359854580956d22d9564a16c9/wal-000000040 (ops 191-195)
I20260812 06:16:34.467597 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: LogGCOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:34.469522 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=6.157687
I20260812 06:16:34.490590 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.021s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8655,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:34.491217 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9): perf score=2.188937
I20260812 06:16:34.506892 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: FlushDeltaMemStoresOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.507455 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9): 493 bytes on disk
I20260812 06:16:34.507977 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: UndoDeltaBlockGCOp(fefbd37359854580956d22d9564a16c9) 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:16:34.508548 20089 maintenance_manager.cc:419] P 108d5cac4fc74362993e8dfe2cba8f19: Scheduling MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9): perf score=1.000000
I20260812 06:16:34.543962 19678 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.101s	user 1.892s	sys 0.171s
I20260812 06:16:34.651640 19678 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.001s	sys 0.000s
I20260812 06:16:34.652314 19678 tablet_server.cc:179] TabletServer@127.19.55.129:0 shutting down...
I20260812 06:16:34.729435 20019 maintenance_manager.cc:643] P 108d5cac4fc74362993e8dfe2cba8f19: MajorDeltaCompactionOp(fefbd37359854580956d22d9564a16c9) complete. Timing: real 0.221s	user 0.152s	sys 0.068s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082164,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":315,"lbm_read_time_us":17053,"lbm_reads_lt_1ms":870,"lbm_write_time_us":38514,"lbm_writes_lt_1ms":843,"mutex_wait_us":2,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":20224,"thread_start_us":82,"threads_started":1,"update_count":4000}
I20260812 06:16:34.730821 19678 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.731199 19678 tablet_replica.cc:333] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19: stopping tablet replica
I20260812 06:16:34.731380 19678 raft_consensus.cc:2243] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.731570 19678 raft_consensus.cc:2272] T fefbd37359854580956d22d9564a16c9 P 108d5cac4fc74362993e8dfe2cba8f19 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.749023 19678 tablet_server.cc:196] TabletServer@127.19.55.129:0 shutdown complete.
I20260812 06:16:34.801152 19678 master.cc:562] Master@127.19.55.190:37925 shutting down...
I20260812 06:16:34.805109 19678 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.805310 19678 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.805361 19678 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6f605600599c44b6ad06f30888a10c2c: stopping tablet replica
I20260812 06:16:34.818336 19678 master.cc:584] Master@127.19.55.190:37925 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5657 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12166 ms total)

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