[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:22.154873 11432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.42.62:37801
I20260812 06:20:22.156126 11432 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:20:22.156948 11432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.165197 11443 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.165197 11438 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.165526 11440 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:22.165526 11432 server_base.cc:1061] running on GCE node
I20260812 06:20:22.166291 11432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.166396 11432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:22.166426 11432 hybrid_clock.cc:648] HybridClock initialized: now 1786515622166424 us; error 0 us; skew 500 ppm
I20260812 06:20:22.168771 11432 webserver.cc:533] Webserver started at http://127.11.42.62:39919/ using document root <none> and password file <none>
I20260812 06:20:22.169392 11432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.169456 11432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.169682 11432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.171583 11432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/master-0-root/instance:
uuid: "23215ff714f34f96bf359ed15240fd0d"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-h3ft"
I20260812 06:20:22.175945 11432 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:20:22.178615 11453 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.179972 11432 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:20:22.180150 11432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/master-0-root
uuid: "23215ff714f34f96bf359ed15240fd0d"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-h3ft"
I20260812 06:20:22.180272 11432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:22.195792 11432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.196507 11432 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:20:22.196703 11432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.205693 11432 rpc_server.cc:307] RPC server started. Bound to: 127.11.42.62:37801
I20260812 06:20:22.205710 11533 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.42.62:37801 every 8 connection(s)
I20260812 06:20:22.208956 11535 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.215550 11535 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: Bootstrap starting.
I20260812 06:20:22.218530 11535 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.219712 11535 log.cc:826] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:22.222193 11535 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: No bootstrap required, opened a new log
I20260812 06:20:22.225502 11535 raft_consensus.cc:359] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER }
I20260812 06:20:22.225700 11535 raft_consensus.cc:385] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.225776 11535 raft_consensus.cc:740] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 23215ff714f34f96bf359ed15240fd0d, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.226540 11535 consensus_queue.cc:260] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [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: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER }
I20260812 06:20:22.226709 11535 raft_consensus.cc:399] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.226811 11535 raft_consensus.cc:493] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.227001 11535 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.227980 11535 raft_consensus.cc:515] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER }
I20260812 06:20:22.228502 11535 leader_election.cc:304] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [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: 23215ff714f34f96bf359ed15240fd0d; no voters: 
I20260812 06:20:22.228904 11535 leader_election.cc:290] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.229193 11538 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.229647 11538 raft_consensus.cc:697] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 1 LEADER]: Becoming Leader. State: Replica: 23215ff714f34f96bf359ed15240fd0d, State: Running, Role: LEADER
I20260812 06:20:22.230218 11535 sys_catalog.cc:565] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.230175 11538 consensus_queue.cc:237] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [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: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER }
I20260812 06:20:22.233065 11432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:22.233103 11539 sys_catalog.cc:455] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "23215ff714f34f96bf359ed15240fd0d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER } }
I20260812 06:20:22.233222 11539 sys_catalog.cc:458] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.233146 11541 sys_catalog.cc:455] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 23215ff714f34f96bf359ed15240fd0d. Latest consensus state: current_term: 1 leader_uuid: "23215ff714f34f96bf359ed15240fd0d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23215ff714f34f96bf359ed15240fd0d" member_type: VOTER } }
I20260812 06:20:22.233310 11541 sys_catalog.cc:458] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [sys.catalog]: This master's current role is: LEADER
W20260812 06:20:22.235932 11566 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:22.236025 11566 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:22.236104 11568 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.237084 11568 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.243943 11568 catalog_manager.cc:1383] Generated new cluster ID: 1f01257de501451cb1ed18ec80930e2c
I20260812 06:20:22.244052 11568 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.255170 11568 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.256534 11568 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.268185 11568 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: Generated new TSK 0
I20260812 06:20:22.269102 11568 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.298878 11432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.302165 11580 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.302258 11585 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:22.302368 11583 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:22.303246 11432 server_base.cc:1061] running on GCE node
I20260812 06:20:22.303506 11432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.303574 11432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:22.303602 11432 hybrid_clock.cc:648] HybridClock initialized: now 1786515622303601 us; error 0 us; skew 500 ppm
I20260812 06:20:22.304797 11432 webserver.cc:533] Webserver started at http://127.11.42.1:41719/ using document root <none> and password file <none>
I20260812 06:20:22.304998 11432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.305080 11432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.305198 11432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.305706 11432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/instance:
uuid: "2f942283e84644849ed46f07669c7b53"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-h3ft"
I20260812 06:20:22.307539 11432 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:22.308701 11595 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.308982 11432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.309065 11432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root
uuid: "2f942283e84644849ed46f07669c7b53"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-h3ft"
I20260812 06:20:22.309171 11432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:22.320698 11432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.321270 11432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.321919 11432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.322991 11432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.323151 11432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.323230 11432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.323273 11432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.331626 11432 rpc_server.cc:307] RPC server started. Bound to: 127.11.42.1:35495
I20260812 06:20:22.331758 11685 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.42.1:35495 every 8 connection(s)
I20260812 06:20:22.344134 11687 heartbeater.cc:344] Connected to a master server at 127.11.42.62:37801
I20260812 06:20:22.344472 11687 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.345127 11687 heartbeater.cc:507] Master 127.11.42.62:37801 requested a full tablet report, sending...
I20260812 06:20:22.346987 11478 ts_manager.cc:194] Registered new tserver with Master: 2f942283e84644849ed46f07669c7b53 (127.11.42.1:35495)
I20260812 06:20:22.347133 11432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014638602s
I20260812 06:20:22.348729 11478 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40388
I20260812 06:20:22.359082 11478 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40402:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:22.378190 11631 tablet_service.cc:1511] Processing CreateTablet for tablet 8d5b1cf93c7545abb52020f0489e2333 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d71dc50fd99045c69404368c98324316]), partition=
I20260812 06:20:22.378839 11631 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8d5b1cf93c7545abb52020f0489e2333. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.382405 11701 tablet_bootstrap.cc:492] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Bootstrap starting.
I20260812 06:20:22.383741 11701 tablet_bootstrap.cc:654] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.385793 11701 tablet_bootstrap.cc:492] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: No bootstrap required, opened a new log
I20260812 06:20:22.385910 11701 ts_tablet_manager.cc:1403] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Time spent bootstrapping tablet: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:20:22.386559 11701 raft_consensus.cc:359] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2f942283e84644849ed46f07669c7b53" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 35495 } }
I20260812 06:20:22.386691 11701 raft_consensus.cc:385] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.386716 11701 raft_consensus.cc:740] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2f942283e84644849ed46f07669c7b53, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.386893 11701 consensus_queue.cc:260] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [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: "2f942283e84644849ed46f07669c7b53" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 35495 } }
I20260812 06:20:22.386991 11701 raft_consensus.cc:399] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.387104 11701 raft_consensus.cc:493] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.387156 11701 raft_consensus.cc:3060] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.388111 11701 raft_consensus.cc:515] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2f942283e84644849ed46f07669c7b53" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 35495 } }
I20260812 06:20:22.388280 11701 leader_election.cc:304] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [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: 2f942283e84644849ed46f07669c7b53; no voters: 
I20260812 06:20:22.388568 11701 leader_election.cc:290] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.388810 11705 raft_consensus.cc:2804] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.389011 11701 ts_tablet_manager.cc:1434] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:20:22.389220 11705 raft_consensus.cc:697] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 1 LEADER]: Becoming Leader. State: Replica: 2f942283e84644849ed46f07669c7b53, State: Running, Role: LEADER
I20260812 06:20:22.389343 11687 heartbeater.cc:499] Master 127.11.42.62:37801 was elected leader, sending a full tablet report...
I20260812 06:20:22.389518 11705 consensus_queue.cc:237] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [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: "2f942283e84644849ed46f07669c7b53" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 35495 } }
I20260812 06:20:22.393290 11478 catalog_manager.cc:5719] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2f942283e84644849ed46f07669c7b53 (127.11.42.1). New cstate: current_term: 1 leader_uuid: "2f942283e84644849ed46f07669c7b53" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2f942283e84644849ed46f07669c7b53" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 35495 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.467172 11432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.016s	sys 0.012s
I20260812 06:20:22.583438 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333): perf score=11.117440
I20260812 06:20:22.723258 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.139s	user 0.111s	sys 0.028s Metrics: {"bytes_written":8123032,"cfile_init":1,"compiler_manager_pool.queue_time_us":309,"delete_count":0,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":374,"dirs.run_wall_time_us":1058,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31526,"lbm_writes_lt_1ms":465,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":191360,"thread_start_us":216,"threads_started":1,"update_count":990}
I20260812 06:20:22.724829 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling LogGCOp(8d5b1cf93c7545abb52020f0489e2333): free 8725963 bytes of WAL
I20260812 06:20:22.725204 11603 log_reader.cc:385] T 8d5b1cf93c7545abb52020f0489e2333: removed 1 log segments from log reader
I20260812 06:20:22.725307 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000001 (ops 1-6)
I20260812 06:20:22.728364 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: LogGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:22.728806 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:22.745520 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5668,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:20:22.746065 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:22.898468 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.152s	user 0.107s	sys 0.029s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16118654,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":785,"lbm_read_time_us":8203,"lbm_reads_lt_1ms":354,"lbm_write_time_us":24634,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":81664,"thread_start_us":340,"threads_started":5,"update_count":1450}
I20260812 06:20:22.899326 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:22.943336 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.044s	user 0.033s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.943957 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333): 8616793 bytes on disk
I20260812 06:20:22.944546 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.945134 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:23.072026 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":344,"lbm_read_time_us":9664,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20408,"lbm_writes_lt_1ms":343,"mutex_wait_us":122,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":1500}
I20260812 06:20:23.072824 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:23.113076 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.040s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15881,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.113798 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:23.290453 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.176s	user 0.147s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":4158,"lbm_read_time_us":9270,"lbm_reads_lt_1ms":363,"lbm_write_time_us":32612,"lbm_writes_lt_1ms":343,"mutex_wait_us":1058,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.291292 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:23.339344 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.048s	user 0.034s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18748,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.340013 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:23.353302 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.354053 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:23.509101 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.155s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":402,"lbm_read_time_us":10612,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31672,"lbm_writes_lt_1ms":443,"mutex_wait_us":138,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:20:23.509903 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:23.578028 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.068s	user 0.028s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20354,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.578845 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:23.591760 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.592375 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:23.776779 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.184s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":14256,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29790,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:20:23.777685 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:23.832722 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.055s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20765,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:20:23.833626 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:23.849718 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.850486 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.028267 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.177s	user 0.146s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1019,"lbm_read_time_us":14335,"lbm_reads_lt_1ms":472,"lbm_write_time_us":36863,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1524096,"update_count":2000}
I20260812 06:20:24.028904 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:24.079999 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.051s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20996,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.080672 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:24.093703 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.094591 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.243515 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.149s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":378,"lbm_read_time_us":11302,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28808,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:20:24.244270 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:24.297641 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.053s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17658,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.298475 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.308295 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.010s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1518081,"delete_count":0,"lbm_write_time_us":1856,"lbm_writes_lt_1ms":40,"reinsert_count":0,"update_count":185}
I20260812 06:20:24.308840 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.196750
I20260812 06:20:24.317824 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":3206,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:20:24.318375 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.351137 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.033s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":345,"dirs.run_wall_time_us":1720,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:24.352372 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333): 447 bytes on disk
I20260812 06:20:24.353013 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.353560 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.537609 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.184s	user 0.125s	sys 0.043s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631337,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":309,"lbm_read_time_us":11823,"lbm_reads_lt_1ms":465,"lbm_write_time_us":29950,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.538651 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling LogGCOp(8d5b1cf93c7545abb52020f0489e2333): free 124257254 bytes of WAL
I20260812 06:20:24.538965 11603 log_reader.cc:385] T 8d5b1cf93c7545abb52020f0489e2333: removed 12 log segments from log reader
I20260812 06:20:24.539047 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000002 (ops 7-11)
I20260812 06:20:24.539113 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000003 (ops 12-16)
I20260812 06:20:24.539158 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000004 (ops 17-21)
I20260812 06:20:24.539199 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000005 (ops 22-26)
I20260812 06:20:24.539242 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000006 (ops 27-31)
I20260812 06:20:24.539285 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000007 (ops 32-36)
I20260812 06:20:24.539328 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000008 (ops 37-41)
I20260812 06:20:24.539373 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000009 (ops 42-46)
I20260812 06:20:24.539417 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000010 (ops 47-50)
I20260812 06:20:24.539458 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000011 (ops 51-55)
I20260812 06:20:24.539500 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000012 (ops 56-60)
I20260812 06:20:24.539551 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000013 (ops 61-65)
I20260812 06:20:24.577298 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: LogGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.038s	user 0.001s	sys 0.035s Metrics: {}
I20260812 06:20:24.577980 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=15.087375
I20260812 06:20:24.653949 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.076s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16902199,"delete_count":0,"lbm_write_time_us":24894,"lbm_writes_lt_1ms":415,"reinsert_count":0,"update_count":2060}
I20260812 06:20:24.654778 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=6.157687
I20260812 06:20:24.676402 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.021s	user 0.012s	sys 0.007s Metrics: {"bytes_written":7712789,"delete_count":0,"lbm_write_time_us":9285,"lbm_writes_lt_1ms":191,"reinsert_count":0,"update_count":940}
I20260812 06:20:24.677266 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:24.919147 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.242s	user 0.151s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836145,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":17170,"lbm_reads_lt_1ms":672,"lbm_write_time_us":42631,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3000}
I20260812 06:20:24.919713 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=14.095187
I20260812 06:20:24.995689 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.076s	user 0.042s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":30726,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.996472 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:25.009182 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.010046 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:25.221041 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.211s	user 0.131s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":14900,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36644,"lbm_writes_lt_1ms":543,"mutex_wait_us":418,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:25.221850 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=11.118625
I20260812 06:20:25.266918 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.045s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20789,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.267868 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:25.289212 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.021s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6730,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.289848 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:25.459282 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.169s	user 0.114s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1148,"lbm_read_time_us":12038,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26141,"lbm_writes_lt_1ms":443,"mutex_wait_us":387,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:20:25.459946 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=11.118625
I20260812 06:20:25.501505 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.041s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17849,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.502378 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:25.515938 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.516639 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:25.669231 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.152s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1295,"lbm_read_time_us":10852,"lbm_reads_lt_1ms":468,"lbm_write_time_us":30056,"lbm_writes_lt_1ms":443,"mutex_wait_us":368,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:20:25.670113 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=10.126437
I20260812 06:20:25.722162 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.052s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":25895,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.722884 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:25.737771 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.738513 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:25.924741 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.186s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1402,"lbm_read_time_us":11043,"lbm_reads_lt_1ms":472,"lbm_write_time_us":35679,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:20:25.925374 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=11.118625
I20260812 06:20:25.982331 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.057s	user 0.017s	sys 0.035s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":24914,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.983059 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:26.010198 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.027s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.010946 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:26.022863 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.023496 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:26.062456 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1615,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1930,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:26.063562 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling LogGCOp(8d5b1cf93c7545abb52020f0489e2333): free 112692387 bytes of WAL
I20260812 06:20:26.063948 11603 log_reader.cc:385] T 8d5b1cf93c7545abb52020f0489e2333: removed 11 log segments from log reader
I20260812 06:20:26.064035 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000014 (ops 66-70)
I20260812 06:20:26.064100 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000015 (ops 71-75)
I20260812 06:20:26.064169 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000016 (ops 76-80)
I20260812 06:20:26.064225 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000017 (ops 81-85)
I20260812 06:20:26.064294 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000018 (ops 86-90)
I20260812 06:20:26.064337 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000019 (ops 91-95)
I20260812 06:20:26.064383 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000020 (ops 96-100)
I20260812 06:20:26.064427 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000021 (ops 101-105)
I20260812 06:20:26.064473 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000022 (ops 106-110)
I20260812 06:20:26.064518 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000023 (ops 111-115)
I20260812 06:20:26.064561 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000024 (ops 116-120)
I20260812 06:20:26.095670 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: LogGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:26.096311 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333): 448 bytes on disk
I20260812 06:20:26.096985 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333) 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:20:26.097924 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=3.181125
I20260812 06:20:26.118158 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6023,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:26.118868 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:26.131356 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4697,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.132145 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:26.405148 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.273s	user 0.194s	sys 0.072s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938883,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1602,"lbm_read_time_us":21429,"lbm_reads_lt_1ms":775,"lbm_write_time_us":49155,"lbm_writes_lt_1ms":743,"mutex_wait_us":910,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:20:26.406513 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=18.063937
I20260812 06:20:26.469260 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.062s	user 0.031s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28369,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.469909 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:26.486263 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.487041 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:26.672124 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.185s	user 0.120s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1146,"lbm_read_time_us":14760,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36600,"lbm_writes_lt_1ms":643,"mutex_wait_us":339,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":3000}
I20260812 06:20:26.672875 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=14.095187
I20260812 06:20:26.735474 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.062s	user 0.030s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.736105 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:26.750360 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.751120 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:26.949330 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.198s	user 0.134s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":12756,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36679,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":50176,"update_count":2500}
I20260812 06:20:26.950462 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=14.095187
I20260812 06:20:27.026087 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.075s	user 0.038s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28336,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.026760 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:27.041963 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.042699 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:27.250972 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.208s	user 0.137s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":718,"lbm_read_time_us":14096,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37055,"lbm_writes_lt_1ms":543,"mutex_wait_us":200,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:20:27.251855 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=14.095187
I20260812 06:20:27.333778 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.082s	user 0.021s	sys 0.050s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":36006,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.334498 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:27.347756 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.348592 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:27.627138 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.278s	user 0.213s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":15029,"lbm_reads_lt_1ms":572,"lbm_write_time_us":46843,"lbm_writes_lt_1ms":543,"mutex_wait_us":227,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:27.628042 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=18.063937
I20260812 06:20:27.730965 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.103s	user 0.058s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":40590,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:27.731923 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:27.754418 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.022s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.755429 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:27.805145 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushMRSOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.049s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1193506,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1488,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2209,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:27.806279 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling LogGCOp(8d5b1cf93c7545abb52020f0489e2333): free 120553600 bytes of WAL
I20260812 06:20:27.806578 11603 log_reader.cc:385] T 8d5b1cf93c7545abb52020f0489e2333: removed 12 log segments from log reader
I20260812 06:20:27.806648 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000025 (ops 121-125)
I20260812 06:20:27.806720 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000026 (ops 126-130)
I20260812 06:20:27.806773 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000027 (ops 131-134)
I20260812 06:20:27.806816 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000028 (ops 135-139)
I20260812 06:20:27.806860 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000029 (ops 140-144)
I20260812 06:20:27.806911 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000030 (ops 145-148)
I20260812 06:20:27.807027 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000031 (ops 149-153)
I20260812 06:20:27.807086 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000032 (ops 154-158)
I20260812 06:20:27.807140 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000033 (ops 159-163)
I20260812 06:20:27.807192 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000034 (ops 164-168)
I20260812 06:20:27.807240 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000035 (ops 169-173)
I20260812 06:20:27.807281 11603 log.cc:1079] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/8d5b1cf93c7545abb52020f0489e2333/wal-000000036 (ops 174-178)
I20260812 06:20:27.849941 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: LogGCOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.043s	user 0.003s	sys 0.039s Metrics: {}
I20260812 06:20:27.850601 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=3.181125
I20260812 06:20:27.898761 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.048s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7511,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:27.899430 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=2.188937
I20260812 06:20:27.910893 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.911509 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:28.186828 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.275s	user 0.198s	sys 0.076s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041186,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1481,"lbm_read_time_us":21390,"lbm_reads_lt_1ms":874,"lbm_write_time_us":51772,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":512,"threads_started":6,"update_count":4000}
I20260812 06:20:28.188323 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=15.087375
I20260812 06:20:28.257177 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.069s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":25965,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:20:28.258155 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333): 462 bytes on disk
I20260812 06:20:28.258790 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: UndoDeltaBlockGCOp(8d5b1cf93c7545abb52020f0489e2333) 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:20:28.259595 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=4.173312
I20260812 06:20:28.278421 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.019s	user 0.008s	sys 0.007s Metrics: {"bytes_written":6276941,"delete_count":0,"lbm_write_time_us":7926,"lbm_writes_lt_1ms":156,"mutex_wait_us":233,"reinsert_count":0,"update_count":765}
I20260812 06:20:28.279075 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:28.287168 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1518077,"delete_count":0,"lbm_write_time_us":1834,"lbm_writes_lt_1ms":40,"reinsert_count":0,"update_count":185}
I20260812 06:20:28.287918 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333): perf score=1.000000
I20260812 06:20:28.542312 11432 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.075s	user 2.205s	sys 0.178s
I20260812 06:20:28.550158 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: MajorDeltaCompactionOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.262s	user 0.204s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":622,"lbm_read_time_us":16776,"lbm_reads_lt_1ms":673,"lbm_write_time_us":54121,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":3000}
I20260812 06:20:28.550912 11688 maintenance_manager.cc:419] P 2f942283e84644849ed46f07669c7b53: Scheduling FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333): perf score=14.095187
I20260812 06:20:28.587095 11432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.044s	user 0.005s	sys 0.000s
I20260812 06:20:28.588056 11432 tablet_server.cc:179] TabletServer@127.11.42.1:0 shutting down...
I20260812 06:20:28.606951 11603 maintenance_manager.cc:643] P 2f942283e84644849ed46f07669c7b53: FlushDeltaMemStoresOp(8d5b1cf93c7545abb52020f0489e2333) complete. Timing: real 0.056s	user 0.043s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25383,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.607959 11432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:28.608513 11432 tablet_replica.cc:333] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53: stopping tablet replica
I20260812 06:20:28.608807 11432 raft_consensus.cc:2243] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.609113 11432 raft_consensus.cc:2272] T 8d5b1cf93c7545abb52020f0489e2333 P 2f942283e84644849ed46f07669c7b53 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.626629 11432 tablet_server.cc:196] TabletServer@127.11.42.1:0 shutdown complete.
I20260812 06:20:28.633340 11432 master.cc:562] Master@127.11.42.62:37801 shutting down...
I20260812 06:20:28.638670 11432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.639060 11432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.639189 11432 tablet_replica.cc:333] T 00000000000000000000000000000000 P 23215ff714f34f96bf359ed15240fd0d: stopping tablet replica
I20260812 06:20:28.652519 11432 master.cc:584] Master@127.11.42.62:37801 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6611 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:28.765754 11432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.42.62:44251
I20260812 06:20:28.766237 11432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.769302 11736 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:28.769351 11739 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:28.769311 11432 server_base.cc:1061] running on GCE node
W20260812 06:20:28.769363 11737 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:28.769788 11432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.769861 11432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:28.769891 11432 hybrid_clock.cc:648] HybridClock initialized: now 1786515628769889 us; error 0 us; skew 500 ppm
I20260812 06:20:28.772066 11432 webserver.cc:533] Webserver started at http://127.11.42.62:33325/ using document root <none> and password file <none>
I20260812 06:20:28.772297 11432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.772382 11432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.772508 11432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.773020 11432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/master-0-root/instance:
uuid: "ddfc230f857c448582e5f7e97a63534c"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-h3ft"
I20260812 06:20:28.774817 11432 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:28.776119 11749 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.776459 11432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:28.776532 11432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/master-0-root
uuid: "ddfc230f857c448582e5f7e97a63534c"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-h3ft"
I20260812 06:20:28.776607 11432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:28.798743 11432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.799263 11432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.803714 11432 rpc_server.cc:307] RPC server started. Bound to: 127.11.42.62:44251
I20260812 06:20:28.808506 11836 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.42.62:44251 every 8 connection(s)
I20260812 06:20:28.812999 11837 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:28.828493 11837 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c: Bootstrap starting.
I20260812 06:20:28.829783 11837 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.831599 11837 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c: No bootstrap required, opened a new log
I20260812 06:20:28.832194 11837 raft_consensus.cc:359] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER }
I20260812 06:20:28.832310 11837 raft_consensus.cc:385] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.832333 11837 raft_consensus.cc:740] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ddfc230f857c448582e5f7e97a63534c, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.832576 11837 consensus_queue.cc:260] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [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: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER }
I20260812 06:20:28.832654 11837 raft_consensus.cc:399] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.832711 11837 raft_consensus.cc:493] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.832793 11837 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.833761 11837 raft_consensus.cc:515] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER }
I20260812 06:20:28.833936 11837 leader_election.cc:304] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [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: ddfc230f857c448582e5f7e97a63534c; no voters: 
I20260812 06:20:28.834198 11837 leader_election.cc:290] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.834396 11841 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.834631 11841 raft_consensus.cc:697] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 1 LEADER]: Becoming Leader. State: Replica: ddfc230f857c448582e5f7e97a63534c, State: Running, Role: LEADER
I20260812 06:20:28.834796 11841 consensus_queue.cc:237] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [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: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER }
I20260812 06:20:28.834820 11837 sys_catalog.cc:565] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:28.835338 11842 sys_catalog.cc:455] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ddfc230f857c448582e5f7e97a63534c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER } }
I20260812 06:20:28.835455 11842 sys_catalog.cc:458] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.835353 11843 sys_catalog.cc:455] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [sys.catalog]: SysCatalogTable state changed. Reason: New leader ddfc230f857c448582e5f7e97a63534c. Latest consensus state: current_term: 1 leader_uuid: "ddfc230f857c448582e5f7e97a63534c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ddfc230f857c448582e5f7e97a63534c" member_type: VOTER } }
I20260812 06:20:28.835515 11843 sys_catalog.cc:458] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.835786 11845 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:28.836699 11845 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:28.837178 11432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:28.838841 11845 catalog_manager.cc:1383] Generated new cluster ID: 8593819632bd4b73a2408a14c9d40ce6
I20260812 06:20:28.838903 11845 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:28.858707 11845 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:28.859447 11845 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:28.864465 11845 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c: Generated new TSK 0
I20260812 06:20:28.864675 11845 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:28.869957 11432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.872526 11864 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:28.872557 11862 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:28.872640 11867 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:28.872637 11432 server_base.cc:1061] running on GCE node
I20260812 06:20:28.873014 11432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.873065 11432 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:28.873083 11432 hybrid_clock.cc:648] HybridClock initialized: now 1786515628873083 us; error 0 us; skew 500 ppm
I20260812 06:20:28.874269 11432 webserver.cc:533] Webserver started at http://127.11.42.1:35291/ using document root <none> and password file <none>
I20260812 06:20:28.874509 11432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.874665 11432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.874785 11432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.875363 11432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/instance:
uuid: "433e9b3591d244d1a10fa8985a23103a"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-h3ft"
I20260812 06:20:28.877211 11432 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:28.878796 11875 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.879184 11432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:20:28.879277 11432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root
uuid: "433e9b3591d244d1a10fa8985a23103a"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-h3ft"
I20260812 06:20:28.879364 11432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:28.884786 11432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.885213 11432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.885540 11432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:28.886123 11432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:28.886163 11432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.886233 11432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:28.886278 11432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.891450 11432 rpc_server.cc:307] RPC server started. Bound to: 127.11.42.1:38183
I20260812 06:20:28.891494 11973 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.42.1:38183 every 8 connection(s)
I20260812 06:20:28.897967 11974 heartbeater.cc:344] Connected to a master server at 127.11.42.62:44251
I20260812 06:20:28.898169 11974 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:28.898504 11974 heartbeater.cc:507] Master 127.11.42.62:44251 requested a full tablet report, sending...
I20260812 06:20:28.899453 11779 ts_manager.cc:194] Registered new tserver with Master: 433e9b3591d244d1a10fa8985a23103a (127.11.42.1:38183)
I20260812 06:20:28.899865 11432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007862185s
I20260812 06:20:28.900384 11779 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33180
I20260812 06:20:28.909454 11779 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33186:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:28.921628 11925 tablet_service.cc:1511] Processing CreateTablet for tablet 25645ce443294de0ad1ae39a38f6e812 (DEFAULT_TABLE table=heavy-update-compaction-test [id=da4209d5535148f49c4708609a07dbe2]), partition=
I20260812 06:20:28.922137 11925 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 25645ce443294de0ad1ae39a38f6e812. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:28.925225 11993 tablet_bootstrap.cc:492] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Bootstrap starting.
I20260812 06:20:28.926564 11993 tablet_bootstrap.cc:654] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.928231 11993 tablet_bootstrap.cc:492] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: No bootstrap required, opened a new log
I20260812 06:20:28.928390 11993 ts_tablet_manager.cc:1403] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:28.928977 11993 raft_consensus.cc:359] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "433e9b3591d244d1a10fa8985a23103a" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 38183 } }
I20260812 06:20:28.929095 11993 raft_consensus.cc:385] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.929163 11993 raft_consensus.cc:740] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 433e9b3591d244d1a10fa8985a23103a, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.929386 11993 consensus_queue.cc:260] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [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: "433e9b3591d244d1a10fa8985a23103a" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 38183 } }
I20260812 06:20:28.929488 11993 raft_consensus.cc:399] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.929564 11993 raft_consensus.cc:493] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.929636 11993 raft_consensus.cc:3060] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.930673 11993 raft_consensus.cc:515] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "433e9b3591d244d1a10fa8985a23103a" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 38183 } }
I20260812 06:20:28.930866 11993 leader_election.cc:304] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [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: 433e9b3591d244d1a10fa8985a23103a; no voters: 
I20260812 06:20:28.931167 11993 leader_election.cc:290] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.931329 11996 raft_consensus.cc:2804] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.931609 11993 ts_tablet_manager.cc:1434] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:20:28.931648 11996 raft_consensus.cc:697] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 1 LEADER]: Becoming Leader. State: Replica: 433e9b3591d244d1a10fa8985a23103a, State: Running, Role: LEADER
I20260812 06:20:28.931761 11974 heartbeater.cc:499] Master 127.11.42.62:44251 was elected leader, sending a full tablet report...
I20260812 06:20:28.931951 11996 consensus_queue.cc:237] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [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: "433e9b3591d244d1a10fa8985a23103a" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 38183 } }
I20260812 06:20:28.933792 11779 catalog_manager.cc:5719] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a reported cstate change: term changed from 0 to 1, leader changed from <none> to 433e9b3591d244d1a10fa8985a23103a (127.11.42.1). New cstate: current_term: 1 leader_uuid: "433e9b3591d244d1a10fa8985a23103a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "433e9b3591d244d1a10fa8985a23103a" member_type: VOTER last_known_addr { host: "127.11.42.1" port: 38183 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:29.005870 11432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.014s	sys 0.012s
I20260812 06:20:29.142666 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushMRSOp(25645ce443294de0ad1ae39a38f6e812): perf score=15.086190
I20260812 06:20:29.292299 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushMRSOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.149s	user 0.109s	sys 0.036s Metrics: {"bytes_written":8615323,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1046,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35945,"lbm_writes_lt_1ms":567,"mutex_wait_us":1070,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1050}
I20260812 06:20:29.293325 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling LogGCOp(25645ce443294de0ad1ae39a38f6e812): free 8725963 bytes of WAL
I20260812 06:20:29.293615 11884 log_reader.cc:385] T 25645ce443294de0ad1ae39a38f6e812: removed 1 log segments from log reader
I20260812 06:20:29.293689 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000001 (ops 1-6)
I20260812 06:20:29.295868 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: LogGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:29.296367 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:29.310868 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5867,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.311628 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812): 12308958 bytes on disk
I20260812 06:20:29.312218 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.312914 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:29.471174 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.158s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1184,"lbm_read_time_us":13592,"lbm_reads_lt_1ms":360,"lbm_write_time_us":25102,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":432,"threads_started":5,"update_count":1500}
I20260812 06:20:29.471948 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:29.518898 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.047s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.519586 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:29.645774 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.126s	user 0.099s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":155,"lbm_read_time_us":10265,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22473,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":87680,"update_count":1500}
I20260812 06:20:29.646613 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:29.701885 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.055s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19482,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.702508 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:29.715850 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4752,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.716686 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:29.878414 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.162s	user 0.101s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":754,"lbm_read_time_us":12369,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31662,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":46720,"update_count":2000}
I20260812 06:20:29.879549 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:29.942483 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.063s	user 0.020s	sys 0.039s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":20642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.943439 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:29.957054 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.013s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.957578 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:30.131632 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.174s	user 0.110s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":14300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27985,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:20:30.132467 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:30.187907 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.055s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.188503 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:30.199932 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.200583 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:30.339056 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1016,"lbm_read_time_us":10696,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27041,"lbm_writes_lt_1ms":443,"mutex_wait_us":497,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:30.339785 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:30.397378 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.057s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19999,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.398078 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:30.411623 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.412245 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:30.558555 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.146s	user 0.126s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":12665,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28885,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:20:30.559450 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:30.611822 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.052s	user 0.029s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22423,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.612586 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:30.745684 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.133s	user 0.101s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":339,"lbm_read_time_us":9806,"lbm_reads_lt_1ms":363,"lbm_write_time_us":26057,"lbm_writes_lt_1ms":343,"mutex_wait_us":48,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":80384,"update_count":1500}
I20260812 06:20:30.746603 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:30.800516 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.054s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20344,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.801259 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:30.819427 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6600,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.820593 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushMRSOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:30.862743 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushMRSOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.042s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1439,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2687,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:30.863557 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling LogGCOp(25645ce443294de0ad1ae39a38f6e812): free 120553372 bytes of WAL
I20260812 06:20:30.863807 11884 log_reader.cc:385] T 25645ce443294de0ad1ae39a38f6e812: removed 12 log segments from log reader
I20260812 06:20:30.863852 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000002 (ops 7-11)
I20260812 06:20:30.863919 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000003 (ops 12-16)
I20260812 06:20:30.863963 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000004 (ops 17-20)
I20260812 06:20:30.863996 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000005 (ops 21-25)
I20260812 06:20:30.864056 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000006 (ops 26-30)
I20260812 06:20:30.864096 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000007 (ops 31-35)
I20260812 06:20:30.864141 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000008 (ops 36-40)
I20260812 06:20:30.864176 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000009 (ops 41-45)
I20260812 06:20:30.864218 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000010 (ops 46-50)
I20260812 06:20:30.864254 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000011 (ops 51-54)
I20260812 06:20:30.864295 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000012 (ops 55-59)
I20260812 06:20:30.864336 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000013 (ops 60-64)
I20260812 06:20:30.897440 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: LogGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:30.902606 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812): 462 bytes on disk
I20260812 06:20:30.903323 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:20:30.904089 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:30.932785 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.028s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.939502 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:30.959520 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.020s	user 0.014s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.960116 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:31.227485 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.267s	user 0.160s	sys 0.104s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1840,"lbm_read_time_us":20647,"lbm_reads_lt_1ms":674,"lbm_write_time_us":43613,"lbm_writes_lt_1ms":643,"mutex_wait_us":1424,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":132,"threads_started":1,"update_count":3000}
I20260812 06:20:31.228506 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=15.087375
I20260812 06:20:31.303910 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.075s	user 0.046s	sys 0.027s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":33350,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:31.304698 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:31.329916 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.330467 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:31.341814 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.342413 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:31.587139 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.245s	user 0.147s	sys 0.097s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836242,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":290,"lbm_read_time_us":17792,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40955,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":85120,"update_count":3000}
I20260812 06:20:31.587971 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:31.646176 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.058s	user 0.031s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.646917 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:31.826071 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.179s	user 0.117s	sys 0.061s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":622,"lbm_read_time_us":12931,"lbm_reads_lt_1ms":463,"lbm_write_time_us":30290,"lbm_writes_lt_1ms":443,"mutex_wait_us":393,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:20:31.826938 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:31.902122 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.075s	user 0.045s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29101,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.902830 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:31.920153 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.921111 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:32.139279 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.218s	user 0.148s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1533,"lbm_read_time_us":15398,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32079,"lbm_writes_lt_1ms":543,"mutex_wait_us":426,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2500}
I20260812 06:20:32.139991 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:32.212282 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.072s	user 0.041s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27247,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.212996 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:32.225839 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.226761 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:32.426028 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.199s	user 0.132s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1846,"lbm_read_time_us":17041,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34877,"lbm_writes_lt_1ms":543,"mutex_wait_us":659,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:20:32.427030 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:32.488112 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.061s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21327,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:32.488854 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:32.507798 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.508659 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:32.674890 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.166s	user 0.127s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1122,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30954,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:20:32.675586 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:32.719216 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.043s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:32.719883 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushMRSOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:32.766634 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushMRSOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.047s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":316,"dirs.run_wall_time_us":1512,"drs_written":1,"lbm_read_time_us":124,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1795,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:32.767426 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812): 473 bytes on disk
I20260812 06:20:32.767931 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:32.768428 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=3.181125
I20260812 06:20:32.783743 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5185,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:32.784425 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling LogGCOp(25645ce443294de0ad1ae39a38f6e812): free 124257243 bytes of WAL
I20260812 06:20:32.784714 11884 log_reader.cc:385] T 25645ce443294de0ad1ae39a38f6e812: removed 12 log segments from log reader
I20260812 06:20:32.784791 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000014 (ops 65-69)
I20260812 06:20:32.784859 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000015 (ops 70-74)
I20260812 06:20:32.784901 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000016 (ops 75-79)
I20260812 06:20:32.784945 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000017 (ops 80-84)
I20260812 06:20:32.784986 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000018 (ops 85-89)
I20260812 06:20:32.785029 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000019 (ops 90-94)
I20260812 06:20:32.785070 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000020 (ops 95-99)
I20260812 06:20:32.785111 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000021 (ops 100-104)
I20260812 06:20:32.785152 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000022 (ops 105-109)
I20260812 06:20:32.785193 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000023 (ops 110-114)
I20260812 06:20:32.785233 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000024 (ops 115-118)
I20260812 06:20:32.785275 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000025 (ops 119-123)
I20260812 06:20:32.820971 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: LogGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.036s	user 0.003s	sys 0.031s Metrics: {}
I20260812 06:20:32.821591 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:32.845208 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.023s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.845911 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:32.862622 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6506,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.863492 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:33.069190 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.205s	user 0.173s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1139,"lbm_read_time_us":16030,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40701,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":105216,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:20:33.070204 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:33.132325 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.062s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28845,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.133059 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:33.147957 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.148633 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:33.344688 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.196s	user 0.125s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":14776,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37566,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":140800,"update_count":2500}
I20260812 06:20:33.345568 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:33.403540 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.058s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":26374,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.404131 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:33.571326 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.167s	user 0.102s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631189,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1918,"lbm_read_time_us":11282,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27480,"lbm_writes_lt_1ms":443,"mutex_wait_us":418,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:33.572243 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=11.118625
I20260812 06:20:33.620476 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.048s	user 0.043s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21622,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:33.621191 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:33.635717 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:33.636365 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:33.810053 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.174s	user 0.125s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1479,"lbm_read_time_us":13364,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32493,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:33.811211 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:33.873652 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.062s	user 0.034s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":25369,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:33.874451 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:33.894034 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.894692 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:34.054979 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.160s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":11738,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32549,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:20:34.055837 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:34.109679 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.054s	user 0.015s	sys 0.033s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":23875,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:34.110347 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:34.122526 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.123394 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:34.276767 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.153s	user 0.124s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":12011,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28641,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2000}
I20260812 06:20:34.278023 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:34.353085 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.075s	user 0.024s	sys 0.038s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23234,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:34.353905 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:34.367791 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.368409 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:34.551813 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.183s	user 0.127s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1073,"lbm_read_time_us":14982,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30103,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:34.552868 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=10.126437
I20260812 06:20:34.601181 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.047s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23268,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:34.603603 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:34.634706 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.031s	user 0.014s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:34.635527 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushMRSOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:34.672614 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushMRSOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.037s	user 0.026s	sys 0.009s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1623,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2601,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:34.674332 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling LogGCOp(25645ce443294de0ad1ae39a38f6e812): free 132571568 bytes of WAL
I20260812 06:20:34.674778 11884 log_reader.cc:385] T 25645ce443294de0ad1ae39a38f6e812: removed 13 log segments from log reader
I20260812 06:20:34.674867 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000026 (ops 124-128)
I20260812 06:20:34.674937 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000027 (ops 129-133)
I20260812 06:20:34.674980 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000028 (ops 134-138)
I20260812 06:20:34.675055 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000029 (ops 139-142)
I20260812 06:20:34.675101 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000030 (ops 143-147)
I20260812 06:20:34.675146 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000031 (ops 148-152)
I20260812 06:20:34.675189 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000032 (ops 153-157)
I20260812 06:20:34.675232 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000033 (ops 158-162)
I20260812 06:20:34.675276 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000034 (ops 163-167)
I20260812 06:20:34.675320 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000035 (ops 168-172)
I20260812 06:20:34.675395 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000036 (ops 173-176)
I20260812 06:20:34.675470 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000037 (ops 177-181)
I20260812 06:20:34.675518 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000038 (ops 182-186)
I20260812 06:20:34.712909 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: LogGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.038s	user 0.005s	sys 0.031s Metrics: {}
I20260812 06:20:34.713608 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=6.157687
I20260812 06:20:34.749315 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.035s	user 0.019s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14788,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:34.750222 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling LogGCOp(25645ce443294de0ad1ae39a38f6e812): free 8767138 bytes of WAL
I20260812 06:20:34.750554 11884 log_reader.cc:385] T 25645ce443294de0ad1ae39a38f6e812: removed 1 log segments from log reader
I20260812 06:20:34.750628 11884 log.cc:1079] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: Deleting log segment in path: /tmp/dist-test-taskdUtd8K/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622143089-11432-0/minicluster-data/ts-0-root/wals/25645ce443294de0ad1ae39a38f6e812/wal-000000039 (ops 187-191)
I20260812 06:20:34.753072 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: LogGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:34.753507 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:34.990741 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.237s	user 0.130s	sys 0.105s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836257,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1155,"dirs.run_cpu_time_us":768,"dirs.run_wall_time_us":3187,"lbm_read_time_us":17169,"lbm_reads_lt_1ms":665,"lbm_write_time_us":42876,"lbm_writes_lt_1ms":643,"mutex_wait_us":181,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":66816,"thread_start_us":125,"threads_started":1,"update_count":3000}
I20260812 06:20:34.991914 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812): 493 bytes on disk
I20260812 06:20:34.992550 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: UndoDeltaBlockGCOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:20:34.993423 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=14.095187
I20260812 06:20:35.040165 11432 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.034s	user 2.153s	sys 0.195s
I20260812 06:20:35.051728 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.058s	user 0.046s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:35.052551 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812): perf score=2.188937
I20260812 06:20:35.065160 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: FlushDeltaMemStoresOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:35.065934 11975 maintenance_manager.cc:419] P 433e9b3591d244d1a10fa8985a23103a: Scheduling MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812): perf score=1.000000
I20260812 06:20:35.103317 11432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.006s	sys 0.000s
I20260812 06:20:35.104270 11432 tablet_server.cc:179] TabletServer@127.11.42.1:0 shutting down...
I20260812 06:20:35.251844 11884 maintenance_manager.cc:643] P 433e9b3591d244d1a10fa8985a23103a: MajorDeltaCompactionOp(25645ce443294de0ad1ae39a38f6e812) complete. Timing: real 0.186s	user 0.099s	sys 0.080s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512298,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1557,"lbm_read_time_us":11204,"lbm_reads_lt_1ms":518,"lbm_write_time_us":29147,"lbm_writes_lt_1ms":543,"mutex_wait_us":388,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:35.252696 11432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:35.252964 11432 tablet_replica.cc:333] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a: stopping tablet replica
I20260812 06:20:35.253149 11432 raft_consensus.cc:2243] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:35.253358 11432 raft_consensus.cc:2272] T 25645ce443294de0ad1ae39a38f6e812 P 433e9b3591d244d1a10fa8985a23103a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:35.268473 11432 tablet_server.cc:196] TabletServer@127.11.42.1:0 shutdown complete.
I20260812 06:20:35.300841 11432 master.cc:562] Master@127.11.42.62:44251 shutting down...
I20260812 06:20:35.304768 11432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:35.305066 11432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:35.305161 11432 tablet_replica.cc:333] T 00000000000000000000000000000000 P ddfc230f857c448582e5f7e97a63534c: stopping tablet replica
I20260812 06:20:35.318533 11432 master.cc:584] Master@127.11.42.62:44251 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6659 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13271 ms total)

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