[==========] 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:17:55.523567  4762 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.166.190:43423
I20260812 06:17:55.524564  4762 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:17:55.525197  4762 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:55.531629  4768 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:17:55.531629  4770 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:17:55.531697  4762 server_base.cc:1061] running on GCE node
W20260812 06:17:55.531931  4767 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:55.532434  4762 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:55.532532  4762 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:17:55.532595  4762 hybrid_clock.cc:648] HybridClock initialized: now 1786515475532593 us; error 0 us; skew 500 ppm
I20260812 06:17:55.534307  4762 webserver.cc:533] Webserver started at http://127.4.166.190:35121/ using document root <none> and password file <none>
I20260812 06:17:55.534838  4762 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:55.534899  4762 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:55.535151  4762 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:55.536798  4762 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/master-0-root/instance:
uuid: "f0c8fb2a5133455db2b742c6efd3e11d"
format_stamp: "Formatted at 2026-08-12 06:17:55 on dist-test-slave-5k54"
I20260812 06:17:55.540617  4762 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:55.542625  4776 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:17:55.543668  4762 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:55.543766  4762 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/master-0-root
uuid: "f0c8fb2a5133455db2b742c6efd3e11d"
format_stamp: "Formatted at 2026-08-12 06:17:55 on dist-test-slave-5k54"
I20260812 06:17:55.543881  4762 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-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:17:55.560739  4762 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:55.561376  4762 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:17:55.561566  4762 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:55.568917  4762 rpc_server.cc:307] RPC server started. Bound to: 127.4.166.190:43423
I20260812 06:17:55.568977  4837 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.166.190:43423 every 8 connection(s)
I20260812 06:17:55.571108  4838 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:17:55.576493  4838 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: Bootstrap starting.
I20260812 06:17:55.578759  4838 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:55.579701  4838 log.cc:826] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:55.581385  4838 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: No bootstrap required, opened a new log
I20260812 06:17:55.584154  4838 raft_consensus.cc:359] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER }
I20260812 06:17:55.584317  4838 raft_consensus.cc:385] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:55.584395  4838 raft_consensus.cc:740] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f0c8fb2a5133455db2b742c6efd3e11d, State: Initialized, Role: FOLLOWER
I20260812 06:17:55.585078  4838 consensus_queue.cc:260] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [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: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER }
I20260812 06:17:55.585246  4838 raft_consensus.cc:399] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:55.585328  4838 raft_consensus.cc:493] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:55.585460  4838 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:55.586274  4838 raft_consensus.cc:515] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER }
I20260812 06:17:55.586730  4838 leader_election.cc:304] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [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: f0c8fb2a5133455db2b742c6efd3e11d; no voters: 
I20260812 06:17:55.587067  4838 leader_election.cc:290] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:55.587229  4841 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:55.587558  4841 raft_consensus.cc:697] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 1 LEADER]: Becoming Leader. State: Replica: f0c8fb2a5133455db2b742c6efd3e11d, State: Running, Role: LEADER
I20260812 06:17:55.587986  4841 consensus_queue.cc:237] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [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: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER }
I20260812 06:17:55.588145  4838 sys_catalog.cc:565] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:55.589913  4842 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER } }
I20260812 06:17:55.589896  4843 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [sys.catalog]: SysCatalogTable state changed. Reason: New leader f0c8fb2a5133455db2b742c6efd3e11d. Latest consensus state: current_term: 1 leader_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0c8fb2a5133455db2b742c6efd3e11d" member_type: VOTER } }
I20260812 06:17:55.590039  4843 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:55.590039  4842 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:55.590427  4762 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:55.590425  4857 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:55.592651  4857 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:55.597344  4857 catalog_manager.cc:1383] Generated new cluster ID: 776edc782b8c44b2b61e7ca6ffd8cb97
I20260812 06:17:55.597420  4857 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:55.626839  4857 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:55.627822  4857 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:55.637501  4857 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: Generated new TSK 0
I20260812 06:17:55.638156  4857 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:55.655208  4762 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:55.657900  4865 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:17:55.657931  4863 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:17:55.657946  4862 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:55.658234  4762 server_base.cc:1061] running on GCE node
I20260812 06:17:55.658408  4762 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:55.658459  4762 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:17:55.658481  4762 hybrid_clock.cc:648] HybridClock initialized: now 1786515475658481 us; error 0 us; skew 500 ppm
I20260812 06:17:55.659409  4762 webserver.cc:533] Webserver started at http://127.4.166.129:45495/ using document root <none> and password file <none>
I20260812 06:17:55.659603  4762 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:55.659662  4762 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:55.659736  4762 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:55.660214  4762 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/instance:
uuid: "0470cbe774be4c23b54adfcb1d9f54ec"
format_stamp: "Formatted at 2026-08-12 06:17:55 on dist-test-slave-5k54"
I20260812 06:17:55.662014  4762 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:55.663051  4871 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:17:55.663298  4762 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:55.663371  4762 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root
uuid: "0470cbe774be4c23b54adfcb1d9f54ec"
format_stamp: "Formatted at 2026-08-12 06:17:55 on dist-test-slave-5k54"
I20260812 06:17:55.663488  4762 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-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:17:55.688170  4762 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:55.688592  4762 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:55.689078  4762 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:55.690066  4762 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:55.690119  4762 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:55.690178  4762 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:55.690218  4762 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:55.697000  4762 rpc_server.cc:307] RPC server started. Bound to: 127.4.166.129:34255
I20260812 06:17:55.697060  4944 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.166.129:34255 every 8 connection(s)
I20260812 06:17:55.714087  4945 heartbeater.cc:344] Connected to a master server at 127.4.166.190:43423
I20260812 06:17:55.714354  4945 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:55.714843  4945 heartbeater.cc:507] Master 127.4.166.190:43423 requested a full tablet report, sending...
I20260812 06:17:55.716305  4797 ts_manager.cc:194] Registered new tserver with Master: 0470cbe774be4c23b54adfcb1d9f54ec (127.4.166.129:34255)
I20260812 06:17:55.717031  4762 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01920638s
I20260812 06:17:55.717721  4797 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60446
I20260812 06:17:55.726281  4797 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60460:
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:17:55.739464  4903 tablet_service.cc:1511] Processing CreateTablet for tablet f0c4cd64ad0d4a54bd224fc08b8baa17 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d5b0ecb21ed54051b06d9be277739ccf]), partition=
I20260812 06:17:55.739917  4903 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f0c4cd64ad0d4a54bd224fc08b8baa17. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:55.742358  4957 tablet_bootstrap.cc:492] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Bootstrap starting.
I20260812 06:17:55.743768  4957 tablet_bootstrap.cc:654] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:55.745201  4957 tablet_bootstrap.cc:492] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: No bootstrap required, opened a new log
I20260812 06:17:55.745322  4957 ts_tablet_manager.cc:1403] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:55.745792  4957 raft_consensus.cc:359] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0470cbe774be4c23b54adfcb1d9f54ec" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 34255 } }
I20260812 06:17:55.745922  4957 raft_consensus.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:55.745970  4957 raft_consensus.cc:740] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0470cbe774be4c23b54adfcb1d9f54ec, State: Initialized, Role: FOLLOWER
I20260812 06:17:55.746110  4957 consensus_queue.cc:260] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [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: "0470cbe774be4c23b54adfcb1d9f54ec" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 34255 } }
I20260812 06:17:55.746217  4957 raft_consensus.cc:399] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:55.746265  4957 raft_consensus.cc:493] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:55.746320  4957 raft_consensus.cc:3060] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:55.746997  4957 raft_consensus.cc:515] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0470cbe774be4c23b54adfcb1d9f54ec" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 34255 } }
I20260812 06:17:55.747148  4957 leader_election.cc:304] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [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: 0470cbe774be4c23b54adfcb1d9f54ec; no voters: 
I20260812 06:17:55.747387  4957 leader_election.cc:290] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:55.747525  4959 raft_consensus.cc:2804] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:55.747751  4957 ts_tablet_manager.cc:1434] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:55.747967  4959 raft_consensus.cc:697] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 1 LEADER]: Becoming Leader. State: Replica: 0470cbe774be4c23b54adfcb1d9f54ec, State: Running, Role: LEADER
I20260812 06:17:55.748097  4959 consensus_queue.cc:237] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [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: "0470cbe774be4c23b54adfcb1d9f54ec" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 34255 } }
I20260812 06:17:55.748251  4945 heartbeater.cc:499] Master 127.4.166.190:43423 was elected leader, sending a full tablet report...
I20260812 06:17:55.750561  4797 catalog_manager.cc:5719] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec reported cstate change: term changed from 0 to 1, leader changed from <none> to 0470cbe774be4c23b54adfcb1d9f54ec (127.4.166.129). New cstate: current_term: 1 leader_uuid: "0470cbe774be4c23b54adfcb1d9f54ec" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0470cbe774be4c23b54adfcb1d9f54ec" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 34255 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:55.807561  4762 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.008s
I20260812 06:17:55.948454  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=19.054940
I20260812 06:17:56.151049  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.202s	user 0.153s	sys 0.035s Metrics: {"bytes_written":14933034,"cfile_init":1,"compiler_manager_pool.queue_time_us":248,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":891,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46754,"lbm_writes_lt_1ms":821,"mutex_wait_us":1276,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":165,"threads_started":1,"update_count":1820}
I20260812 06:17:56.152185  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): free 20290830 bytes of WAL
I20260812 06:17:56.152518  4876 log_reader.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17: removed 2 log segments from log reader
I20260812 06:17:56.152599  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000001 (ops 1-6)
I20260812 06:17:56.152673  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000002 (ops 7-10)
I20260812 06:17:56.156855  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:56.157224  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=4.173312
I20260812 06:17:56.171412  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5579535,"delete_count":0,"lbm_write_time_us":5597,"lbm_writes_lt_1ms":139,"reinsert_count":0,"update_count":680}
I20260812 06:17:56.172026  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): 16411393 bytes on disk
I20260812 06:17:56.172799  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.173379  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:56.350560  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.177s	user 0.139s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":581,"lbm_read_time_us":14024,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30132,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":302,"threads_started":5,"update_count":2500}
I20260812 06:17:56.351276  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=11.118625
I20260812 06:17:56.387471  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.036s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14965,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.388325  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:56.403739  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5378,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.404197  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:56.525017  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.121s	user 0.090s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":7005,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25006,"lbm_writes_lt_1ms":443,"mutex_wait_us":90,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.525657  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=10.126437
I20260812 06:17:56.565400  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.040s	user 0.006s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15653,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.565866  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:56.580031  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.580528  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:56.698777  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.118s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":441,"lbm_read_time_us":8813,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22278,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:56.699582  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=10.126437
I20260812 06:17:56.739168  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.039s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.739831  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:56.751055  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.751736  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:56.883008  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.131s	user 0.110s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1097,"lbm_read_time_us":8548,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22231,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:17:56.883793  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=10.126437
I20260812 06:17:56.923540  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.039s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13929,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.924196  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:56.934490  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.934940  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.075865  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.141s	user 0.096s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1004,"lbm_read_time_us":11032,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22735,"lbm_writes_lt_1ms":443,"mutex_wait_us":106,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.076431  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=10.126437
I20260812 06:17:57.114109  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16024,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.114642  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:57.130214  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.130692  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.257545  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":7200,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27636,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:57.258214  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=10.126437
I20260812 06:17:57.305835  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20508,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.306427  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:57.323735  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.324219  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.356284  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.032s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:57.357105  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): free 112692320 bytes of WAL
I20260812 06:17:57.357329  4876 log_reader.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17: removed 11 log segments from log reader
I20260812 06:17:57.357376  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000003 (ops 11-15)
I20260812 06:17:57.357403  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000004 (ops 16-20)
I20260812 06:17:57.357421  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000005 (ops 21-25)
I20260812 06:17:57.357465  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000006 (ops 26-30)
I20260812 06:17:57.357510  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000007 (ops 31-35)
I20260812 06:17:57.357540  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000008 (ops 36-40)
I20260812 06:17:57.357590  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000009 (ops 41-45)
I20260812 06:17:57.357631  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000010 (ops 46-50)
I20260812 06:17:57.357693  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000011 (ops 51-55)
I20260812 06:17:57.357740  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000012 (ops 56-60)
I20260812 06:17:57.357779  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000013 (ops 61-65)
I20260812 06:17:57.379086  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.022s	user 0.001s	sys 0.017s Metrics: {}
I20260812 06:17:57.379528  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): 462 bytes on disk
I20260812 06:17:57.379925  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.380383  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=5.165500
I20260812 06:17:57.399533  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.019s	user 0.019s	sys 0.000s Metrics: {"bytes_written":6358990,"delete_count":0,"lbm_write_time_us":7612,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:17:57.399995  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): free 12017983 bytes of WAL
I20260812 06:17:57.400231  4876 log_reader.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17: removed 1 log segments from log reader
I20260812 06:17:57.400291  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000014 (ops 66-70)
I20260812 06:17:57.403199  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:57.403618  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.412428  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2771,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:17:57.412935  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.573876  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.161s	user 0.106s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877283,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":311,"lbm_read_time_us":9837,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32167,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:57.574512  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:57.619498  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.045s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19506,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.619993  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:57.633720  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.634202  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:57.789405  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.155s	user 0.126s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":9693,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28559,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":86400,"update_count":2500}
I20260812 06:17:57.790025  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:57.846007  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.056s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20801,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.846596  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:57.862155  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.862676  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:58.021993  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.159s	user 0.135s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":740,"lbm_read_time_us":9774,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31036,"lbm_writes_lt_1ms":543,"mutex_wait_us":233,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2500}
I20260812 06:17:58.022859  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=12.110812
I20260812 06:17:58.066970  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.044s	user 0.035s	sys 0.007s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":18368,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:17:58.067575  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.196750
I20260812 06:17:58.081033  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:58.081454  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:58.235096  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.153s	user 0.100s	sys 0.044s Metrics: {"cfile_cache_miss":438,"cfile_cache_miss_bytes":20918403,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":467,"lbm_read_time_us":8779,"lbm_reads_lt_1ms":470,"lbm_write_time_us":26155,"lbm_writes_lt_1ms":449,"mutex_wait_us":44,"peak_mem_usage":50935538,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2030}
I20260812 06:17:58.235718  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:58.286715  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.051s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16163761,"delete_count":0,"lbm_write_time_us":20480,"lbm_writes_lt_1ms":397,"reinsert_count":0,"update_count":1970}
I20260812 06:17:58.287261  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:58.311266  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.024s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.311849  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:58.485845  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.174s	user 0.099s	sys 0.064s Metrics: {"cfile_cache_miss":526,"cfile_cache_miss_bytes":24528547,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":13319,"lbm_reads_lt_1ms":566,"lbm_write_time_us":26160,"lbm_writes_lt_1ms":537,"mutex_wait_us":348,"peak_mem_usage":61829306,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2470}
I20260812 06:17:58.486526  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:58.534161  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.047s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21950,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.534703  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:58.546452  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.547024  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:58.704668  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.157s	user 0.083s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1588,"lbm_read_time_us":8925,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26635,"lbm_writes_lt_1ms":543,"mutex_wait_us":439,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:17:58.705224  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:58.753935  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.049s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":19259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.754444  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:58.766520  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.766981  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:58.801005  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1513,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:58.801698  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): free 121459520 bytes of WAL
I20260812 06:17:58.801934  4876 log_reader.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17: removed 12 log segments from log reader
I20260812 06:17:58.801986  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000015 (ops 71-75)
I20260812 06:17:58.802014  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000016 (ops 76-80)
I20260812 06:17:58.802070  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000017 (ops 81-85)
I20260812 06:17:58.802112  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000018 (ops 86-90)
I20260812 06:17:58.802173  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000019 (ops 91-95)
I20260812 06:17:58.802217  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000020 (ops 96-100)
I20260812 06:17:58.802274  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000021 (ops 101-105)
I20260812 06:17:58.802318  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000022 (ops 106-110)
I20260812 06:17:58.802359  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000023 (ops 111-115)
I20260812 06:17:58.802399  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000024 (ops 116-120)
I20260812 06:17:58.802440  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000025 (ops 121-125)
I20260812 06:17:58.802482  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000026 (ops 126-130)
I20260812 06:17:58.827150  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:58.827651  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): 481 bytes on disk
I20260812 06:17:58.828259  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.829144  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=3.181125
I20260812 06:17:58.853637  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.024s	user 0.003s	sys 0.016s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":7323,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:58.854211  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:58.864845  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.865613  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:59.094700  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.229s	user 0.151s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":871,"lbm_read_time_us":15882,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39635,"lbm_writes_lt_1ms":743,"mutex_wait_us":349,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:59.095554  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:59.156728  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.059s	user 0.025s	sys 0.033s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":29710,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.157279  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:59.183205  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.026s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.183733  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:59.195391  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.196204  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:59.417413  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.221s	user 0.139s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877223,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":401,"lbm_read_time_us":15383,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38327,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":3000}
I20260812 06:17:59.418371  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:59.465876  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20825,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.466439  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:59.493567  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.027s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.494081  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:59.504175  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.504711  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:59.700137  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.195s	user 0.120s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":910,"lbm_read_time_us":14012,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33159,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":3000}
I20260812 06:17:59.700770  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:59.774348  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.073s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20138,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.774835  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:17:59.785463  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.785961  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:17:59.942461  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.156s	user 0.121s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":11471,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25602,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:59.946300  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:17:59.994225  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18510,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.994733  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:18:00.005606  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.006130  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:18:00.182250  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.176s	user 0.107s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":573,"lbm_read_time_us":11477,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28585,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":37376,"update_count":2500}
I20260812 06:18:00.182780  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=14.095187
I20260812 06:18:00.245612  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.063s	user 0.045s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.246181  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:18:00.256749  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.257208  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:18:00.293749  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushMRSOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.036s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1462,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2093,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:00.294415  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): free 120553636 bytes of WAL
I20260812 06:18:00.294641  4876 log_reader.cc:385] T f0c4cd64ad0d4a54bd224fc08b8baa17: removed 12 log segments from log reader
I20260812 06:18:00.294684  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000027 (ops 131-134)
I20260812 06:18:00.294713  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000028 (ops 135-139)
I20260812 06:18:00.294765  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000029 (ops 140-144)
I20260812 06:18:00.294806  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000030 (ops 145-148)
I20260812 06:18:00.294855  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000031 (ops 149-153)
I20260812 06:18:00.294898  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000032 (ops 154-158)
I20260812 06:18:00.294921  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000033 (ops 159-163)
I20260812 06:18:00.294960  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000034 (ops 164-168)
I20260812 06:18:00.295001  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000035 (ops 169-173)
I20260812 06:18:00.295040  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000036 (ops 174-178)
I20260812 06:18:00.295080  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000037 (ops 179-183)
I20260812 06:18:00.295123  4876 log.cc:1079] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/f0c4cd64ad0d4a54bd224fc08b8baa17/wal-000000038 (ops 184-188)
I20260812 06:18:00.319031  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: LogGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:00.319521  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:18:00.338281  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.338740  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=2.188937
I20260812 06:18:00.348965  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.349391  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17): 463 bytes on disk
I20260812 06:18:00.349792  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: UndoDeltaBlockGCOp(f0c4cd64ad0d4a54bd224fc08b8baa17) 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:18:00.350787  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=1.000000
I20260812 06:18:00.584955  4762 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.777s	user 1.759s	sys 0.157s
I20260812 06:18:00.587245  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: MajorDeltaCompactionOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.236s	user 0.150s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":391,"lbm_read_time_us":15626,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39159,"lbm_writes_lt_1ms":743,"mutex_wait_us":193,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:00.587980  4946 maintenance_manager.cc:419] P 0470cbe774be4c23b54adfcb1d9f54ec: Scheduling FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17): perf score=18.063937
I20260812 06:18:00.616631  4762 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.003s	sys 0.000s
I20260812 06:18:00.617260  4762 tablet_server.cc:179] TabletServer@127.4.166.129:0 shutting down...
I20260812 06:18:00.643914  4876 maintenance_manager.cc:643] P 0470cbe774be4c23b54adfcb1d9f54ec: FlushDeltaMemStoresOp(f0c4cd64ad0d4a54bd224fc08b8baa17) complete. Timing: real 0.056s	user 0.024s	sys 0.031s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25400,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:00.644517  4762 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:00.644886  4762 tablet_replica.cc:333] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec: stopping tablet replica
I20260812 06:18:00.645107  4762 raft_consensus.cc:2243] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:00.645325  4762 raft_consensus.cc:2272] T f0c4cd64ad0d4a54bd224fc08b8baa17 P 0470cbe774be4c23b54adfcb1d9f54ec [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:00.649569  4762 tablet_server.cc:196] TabletServer@127.4.166.129:0 shutdown complete.
I20260812 06:18:00.653853  4762 master.cc:562] Master@127.4.166.190:43423 shutting down...
I20260812 06:18:00.657444  4762 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:00.657564  4762 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:00.657615  4762 tablet_replica.cc:333] T 00000000000000000000000000000000 P f0c8fb2a5133455db2b742c6efd3e11d: stopping tablet replica
I20260812 06:18:00.669811  4762 master.cc:584] Master@127.4.166.190:43423 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5234 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:00.757203  4762 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.166.190:35713
I20260812 06:18:00.757625  4762 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:00.759582  4976 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:18:00.759629  4979 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:18:00.759698  4762 server_base.cc:1061] running on GCE node
W20260812 06:18:00.759797  4977 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:18:00.760005  4762 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.760052  4762 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:18:00.760068  4762 hybrid_clock.cc:648] HybridClock initialized: now 1786515480760067 us; error 0 us; skew 500 ppm
I20260812 06:18:00.760850  4762 webserver.cc:533] Webserver started at http://127.4.166.190:32897/ using document root <none> and password file <none>
I20260812 06:18:00.761021  4762 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.761066  4762 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.761171  4762 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.761561  4762 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/master-0-root/instance:
uuid: "6baeaebe456e4928b072edf6a15c53e5"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-5k54"
I20260812 06:18:00.763036  4762 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:00.764039  4984 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:18:00.764281  4762 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:00.764391  4762 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/master-0-root
uuid: "6baeaebe456e4928b072edf6a15c53e5"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-5k54"
I20260812 06:18:00.764478  4762 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-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:18:00.785250  4762 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.785624  4762 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.789806  4762 rpc_server.cc:307] RPC server started. Bound to: 127.4.166.190:35713
I20260812 06:18:00.791350  5040 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.166.190:35713 every 8 connection(s)
I20260812 06:18:00.792294  5042 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:18:00.807461  5042 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5: Bootstrap starting.
I20260812 06:18:00.808254  5042 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.809235  5042 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5: No bootstrap required, opened a new log
I20260812 06:18:00.809603  5042 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER }
I20260812 06:18:00.809688  5042 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.809711  5042 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6baeaebe456e4928b072edf6a15c53e5, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.809814  5042 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [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: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER }
I20260812 06:18:00.809872  5042 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.809893  5042 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.809921  5042 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.810566  5042 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER }
I20260812 06:18:00.810678  5042 leader_election.cc:304] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [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: 6baeaebe456e4928b072edf6a15c53e5; no voters: 
I20260812 06:18:00.810825  5042 leader_election.cc:290] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.811003  5046 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.811192  5046 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 1 LEADER]: Becoming Leader. State: Replica: 6baeaebe456e4928b072edf6a15c53e5, State: Running, Role: LEADER
I20260812 06:18:00.811335  5042 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:00.811355  5046 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [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: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER }
I20260812 06:18:00.811864  5048 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6baeaebe456e4928b072edf6a15c53e5. Latest consensus state: current_term: 1 leader_uuid: "6baeaebe456e4928b072edf6a15c53e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER } }
I20260812 06:18:00.811848  5047 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6baeaebe456e4928b072edf6a15c53e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6baeaebe456e4928b072edf6a15c53e5" member_type: VOTER } }
I20260812 06:18:00.811966  5048 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.811975  5047 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:00.812278  5051 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:00.813133  5051 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:00.813339  4762 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:00.814949  5051 catalog_manager.cc:1383] Generated new cluster ID: 35798120d81f439e977fe423ce9308ca
I20260812 06:18:00.815011  5051 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:00.831020  5051 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:00.831562  5051 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:00.840884  5051 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5: Generated new TSK 0
I20260812 06:18:00.841048  5051 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:00.845608  4762 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:00.847404  5065 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:18:00.847592  5068 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:18:00.847492  5066 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:18:00.847699  4762 server_base.cc:1061] running on GCE node
I20260812 06:18:00.847915  4762 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:00.847976  4762 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:18:00.848002  4762 hybrid_clock.cc:648] HybridClock initialized: now 1786515480848001 us; error 0 us; skew 500 ppm
I20260812 06:18:00.848817  4762 webserver.cc:533] Webserver started at http://127.4.166.129:36211/ using document root <none> and password file <none>
I20260812 06:18:00.848997  4762 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:00.849067  4762 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:00.849146  4762 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:00.849535  4762 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/instance:
uuid: "e5c246eb75054d4787b23ca94f717925"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-5k54"
I20260812 06:18:00.851060  4762 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:00.852026  5073 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:18:00.852276  4762 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:00.852371  4762 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root
uuid: "e5c246eb75054d4787b23ca94f717925"
format_stamp: "Formatted at 2026-08-12 06:18:00 on dist-test-slave-5k54"
I20260812 06:18:00.852455  4762 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-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:18:00.858825  4762 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:00.859141  4762 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:00.859488  4762 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:00.859931  4762 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:00.860000  4762 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.860049  4762 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:00.860100  4762 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:00.864354  4762 rpc_server.cc:307] RPC server started. Bound to: 127.4.166.129:38051
I20260812 06:18:00.864382  5141 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.166.129:38051 every 8 connection(s)
I20260812 06:18:00.872745  5142 heartbeater.cc:344] Connected to a master server at 127.4.166.190:35713
I20260812 06:18:00.872861  5142 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:00.873137  5142 heartbeater.cc:507] Master 127.4.166.190:35713 requested a full tablet report, sending...
I20260812 06:18:00.873920  5001 ts_manager.cc:194] Registered new tserver with Master: e5c246eb75054d4787b23ca94f717925 (127.4.166.129:38051)
I20260812 06:18:00.874825  4762 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010020108s
I20260812 06:18:00.874974  5001 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38034
I20260812 06:18:00.882309  5001 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38042:
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:18:00.890576  5103 tablet_service.cc:1511] Processing CreateTablet for tablet 94fd95ca0dea4404843f8b493d467271 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6abb143b64314e38b8c1e1dbc2a03ca7]), partition=
I20260812 06:18:00.890852  5103 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 94fd95ca0dea4404843f8b493d467271. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:00.892843  5155 tablet_bootstrap.cc:492] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Bootstrap starting.
I20260812 06:18:00.893791  5155 tablet_bootstrap.cc:654] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:00.894794  5155 tablet_bootstrap.cc:492] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: No bootstrap required, opened a new log
I20260812 06:18:00.894910  5155 ts_tablet_manager.cc:1403] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:00.895319  5155 raft_consensus.cc:359] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5c246eb75054d4787b23ca94f717925" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 38051 } }
I20260812 06:18:00.895401  5155 raft_consensus.cc:385] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:00.895486  5155 raft_consensus.cc:740] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e5c246eb75054d4787b23ca94f717925, State: Initialized, Role: FOLLOWER
I20260812 06:18:00.895628  5155 consensus_queue.cc:260] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [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: "e5c246eb75054d4787b23ca94f717925" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 38051 } }
I20260812 06:18:00.895713  5155 raft_consensus.cc:399] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:00.895771  5155 raft_consensus.cc:493] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:00.895828  5155 raft_consensus.cc:3060] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:00.896673  5155 raft_consensus.cc:515] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5c246eb75054d4787b23ca94f717925" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 38051 } }
I20260812 06:18:00.896816  5155 leader_election.cc:304] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [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: e5c246eb75054d4787b23ca94f717925; no voters: 
I20260812 06:18:00.897032  5155 leader_election.cc:290] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:00.897151  5157 raft_consensus.cc:2804] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:00.897367  5155 ts_tablet_manager.cc:1434] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:00.897404  5157 raft_consensus.cc:697] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 1 LEADER]: Becoming Leader. State: Replica: e5c246eb75054d4787b23ca94f717925, State: Running, Role: LEADER
I20260812 06:18:00.897418  5142 heartbeater.cc:499] Master 127.4.166.190:35713 was elected leader, sending a full tablet report...
I20260812 06:18:00.897573  5157 consensus_queue.cc:237] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [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: "e5c246eb75054d4787b23ca94f717925" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 38051 } }
I20260812 06:18:00.898813  5001 catalog_manager.cc:5719] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 reported cstate change: term changed from 0 to 1, leader changed from <none> to e5c246eb75054d4787b23ca94f717925 (127.4.166.129). New cstate: current_term: 1 leader_uuid: "e5c246eb75054d4787b23ca94f717925" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e5c246eb75054d4787b23ca94f717925" member_type: VOTER last_known_addr { host: "127.4.166.129" port: 38051 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:00.957758  4762 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.019s	sys 0.004s
I20260812 06:18:01.115283  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushMRSOp(94fd95ca0dea4404843f8b493d467271): perf score=23.023690
I20260812 06:18:01.282205  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushMRSOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.167s	user 0.131s	sys 0.033s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":925,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45402,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:01.282824  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling LogGCOp(94fd95ca0dea4404843f8b493d467271): free 20743880 bytes of WAL
I20260812 06:18:01.283051  5078 log_reader.cc:385] T 94fd95ca0dea4404843f8b493d467271: removed 2 log segments from log reader
I20260812 06:18:01.283093  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000001 (ops 1-6)
I20260812 06:18:01.283121  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000002 (ops 7-11)
I20260812 06:18:01.287396  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: LogGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:01.287983  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271): 20513816 bytes on disk
I20260812 06:18:01.288457  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.288848  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:01.314030  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.025s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.314455  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:01.324242  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.324623  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:01.489003  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.164s	user 0.121s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815804,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":495,"lbm_read_time_us":10913,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30049,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":345,"threads_started":5,"update_count":2500}
I20260812 06:18:01.489600  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:01.540233  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.050s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18931,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.540642  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:01.551343  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.551918  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:01.701103  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.149s	user 0.124s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1016,"lbm_read_time_us":10918,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26771,"lbm_writes_lt_1ms":543,"mutex_wait_us":261,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:01.701896  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=11.118625
I20260812 06:18:01.737397  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":13210026,"delete_count":0,"lbm_write_time_us":15574,"lbm_writes_lt_1ms":325,"reinsert_count":0,"update_count":1610}
I20260812 06:18:01.737972  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:01.749306  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:01.749735  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:01.898432  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.149s	user 0.081s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713254,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":9810,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24980,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:18:01.899121  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:01.949486  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.050s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17295,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.949970  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:01.968677  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.019s	user 0.004s	sys 0.013s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.969183  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:02.154727  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.185s	user 0.119s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":10828,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29568,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:02.155366  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:02.207367  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.052s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19859,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.207937  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:02.220013  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.220577  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:02.399679  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.179s	user 0.109s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":10338,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29656,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2500}
I20260812 06:18:02.400373  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:02.449612  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.049s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19273,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.450197  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:02.460847  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.461568  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushMRSOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:02.495096  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushMRSOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1515,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1574,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:02.495735  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling LogGCOp(94fd95ca0dea4404843f8b493d467271): free 124257243 bytes of WAL
I20260812 06:18:02.495993  5078 log_reader.cc:385] T 94fd95ca0dea4404843f8b493d467271: removed 12 log segments from log reader
I20260812 06:18:02.496068  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000003 (ops 12-16)
I20260812 06:18:02.496104  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000004 (ops 17-21)
I20260812 06:18:02.496135  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000005 (ops 22-26)
I20260812 06:18:02.496169  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000006 (ops 27-31)
I20260812 06:18:02.496203  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000007 (ops 32-36)
I20260812 06:18:02.496234  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000008 (ops 37-41)
I20260812 06:18:02.496258  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000009 (ops 42-46)
I20260812 06:18:02.496285  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000010 (ops 47-50)
I20260812 06:18:02.496315  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000011 (ops 51-55)
I20260812 06:18:02.496351  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000012 (ops 56-60)
I20260812 06:18:02.496376  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000013 (ops 61-65)
I20260812 06:18:02.496397  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000014 (ops 66-70)
I20260812 06:18:02.523912  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: LogGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:02.524425  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271): 462 bytes on disk
I20260812 06:18:02.524832  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.525413  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=3.181125
I20260812 06:18:02.544708  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.019s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4542,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.545236  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:02.554829  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.555394  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:02.789047  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.233s	user 0.131s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":766,"lbm_read_time_us":15893,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36400,"lbm_writes_lt_1ms":743,"mutex_wait_us":342,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:18:02.789765  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=18.063937
I20260812 06:18:02.843878  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.054s	user 0.020s	sys 0.032s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23638,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:02.844347  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:03.011091  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.167s	user 0.113s	sys 0.053s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815566,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":668,"lbm_read_time_us":12580,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25896,"lbm_writes_lt_1ms":543,"mutex_wait_us":385,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:03.011879  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:03.069703  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.057s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22006,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.070258  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:03.080724  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.081156  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:03.274943  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.194s	user 0.122s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":13256,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31347,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:03.275693  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:03.332965  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.057s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.333520  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:03.343894  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.344316  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:03.534538  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.190s	user 0.112s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":11639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29650,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:18:03.535187  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:03.589906  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.054s	user 0.032s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23058,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.590374  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:03.600906  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.601542  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:03.784649  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.183s	user 0.144s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":894,"lbm_read_time_us":12154,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28971,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:03.785197  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:03.833647  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22999,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.834163  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:03.849365  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.849888  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushMRSOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:03.905081  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushMRSOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.055s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1330,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2359,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:03.906035  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=6.157687
I20260812 06:18:03.935491  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.029s	user 0.014s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12733,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:03.936141  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling LogGCOp(94fd95ca0dea4404843f8b493d467271): free 120553382 bytes of WAL
I20260812 06:18:03.936450  5078 log_reader.cc:385] T 94fd95ca0dea4404843f8b493d467271: removed 12 log segments from log reader
I20260812 06:18:03.936520  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000015 (ops 71-75)
I20260812 06:18:03.936573  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000016 (ops 76-80)
I20260812 06:18:03.936614  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000017 (ops 81-85)
I20260812 06:18:03.936659  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000018 (ops 86-90)
I20260812 06:18:03.936702  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000019 (ops 91-94)
I20260812 06:18:03.936745  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000020 (ops 95-99)
I20260812 06:18:03.936786  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000021 (ops 100-104)
I20260812 06:18:03.936831  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000022 (ops 105-108)
I20260812 06:18:03.936872  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000023 (ops 109-113)
I20260812 06:18:03.936914  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000024 (ops 114-118)
I20260812 06:18:03.936966  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000025 (ops 119-123)
I20260812 06:18:03.937011  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000026 (ops 124-128)
I20260812 06:18:03.960636  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: LogGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:03.961125  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:03.971642  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.972064  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271): 446 bytes on disk
I20260812 06:18:03.972457  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.972909  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:04.235740  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.263s	user 0.176s	sys 0.083s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":808,"lbm_read_time_us":19083,"lbm_reads_lt_1ms":870,"lbm_write_time_us":42235,"lbm_writes_lt_1ms":843,"mutex_wait_us":225,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":83,"threads_started":1,"update_count":4000}
I20260812 06:18:04.236509  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=18.063937
I20260812 06:18:04.306836  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.070s	user 0.043s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":28309,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:04.307282  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:04.318468  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.319077  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:04.517998  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.199s	user 0.131s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":12715,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32429,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:18:04.518798  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:04.578814  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.060s	user 0.032s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27201,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:04.579284  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=3.181125
I20260812 06:18:04.598855  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5197,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:04.599334  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:04.609050  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3663,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.609447  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:04.807833  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.198s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":568,"lbm_read_time_us":13684,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32785,"lbm_writes_lt_1ms":643,"mutex_wait_us":270,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":3000}
I20260812 06:18:04.808674  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:04.864385  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.055s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27986,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.864974  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:04.880674  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.015s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.881256  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:05.066906  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.185s	user 0.119s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":12017,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32701,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":76800,"update_count":2500}
I20260812 06:18:05.067564  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:05.124688  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.057s	user 0.038s	sys 0.009s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20283,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.125190  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:05.137828  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.138445  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:05.299048  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.160s	user 0.097s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":154,"lbm_read_time_us":10850,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26313,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:05.299836  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=14.095187
I20260812 06:18:05.359197  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.059s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23500,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.359831  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:05.370527  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.370954  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushMRSOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:05.410832  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushMRSOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":313,"dirs.run_wall_time_us":1546,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2054,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:05.411602  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling LogGCOp(94fd95ca0dea4404843f8b493d467271): free 112692556 bytes of WAL
I20260812 06:18:05.411815  5078 log_reader.cc:385] T 94fd95ca0dea4404843f8b493d467271: removed 11 log segments from log reader
I20260812 06:18:05.411876  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000027 (ops 129-133)
I20260812 06:18:05.411931  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000028 (ops 134-138)
I20260812 06:18:05.411967  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000029 (ops 139-143)
I20260812 06:18:05.412003  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000030 (ops 144-148)
I20260812 06:18:05.412074  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000031 (ops 149-153)
I20260812 06:18:05.412144  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000032 (ops 154-158)
I20260812 06:18:05.412187  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000033 (ops 159-163)
I20260812 06:18:05.412247  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000034 (ops 164-168)
I20260812 06:18:05.412286  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000035 (ops 169-173)
I20260812 06:18:05.412323  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000036 (ops 174-178)
I20260812 06:18:05.412358  5078 log.cc:1079] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: Deleting log segment in path: /tmp/dist-test-task9rYbkO/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515475512999-4762-0/minicluster-data/ts-0-root/wals/94fd95ca0dea4404843f8b493d467271/wal-000000037 (ops 179-183)
I20260812 06:18:05.436331  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: LogGCOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:05.436730  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271): 463 bytes on disk
I20260812 06:18:05.437193  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: UndoDeltaBlockGCOp(94fd95ca0dea4404843f8b493d467271) 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:18:05.437731  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:05.456300  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.018s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.456734  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:05.470482  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.471017  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:05.708352  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.237s	user 0.121s	sys 0.108s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1613,"lbm_read_time_us":14233,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43185,"lbm_writes_lt_1ms":743,"mutex_wait_us":285,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":107,"threads_started":1,"update_count":3500}
I20260812 06:18:05.709168  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=18.063937
I20260812 06:18:05.773458  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.064s	user 0.043s	sys 0.019s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28610,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:05.774001  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271): perf score=2.188937
I20260812 06:18:05.789745  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: FlushDeltaMemStoresOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.790407  5143 maintenance_manager.cc:419] P e5c246eb75054d4787b23ca94f717925: Scheduling MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271): perf score=1.000000
I20260812 06:18:05.814450  4762 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.857s	user 1.848s	sys 0.163s
I20260812 06:18:05.867166  4762 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.052s	user 0.001s	sys 0.000s
I20260812 06:18:05.867678  4762 tablet_server.cc:179] TabletServer@127.4.166.129:0 shutting down...
I20260812 06:18:05.938714  5078 maintenance_manager.cc:643] P e5c246eb75054d4787b23ca94f717925: MajorDeltaCompactionOp(94fd95ca0dea4404843f8b493d467271) complete. Timing: real 0.148s	user 0.120s	sys 0.027s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":10812,"lbm_reads_lt_1ms":668,"lbm_write_time_us":28732,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3000}
I20260812 06:18:05.939783  4762 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:05.940018  4762 tablet_replica.cc:333] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925: stopping tablet replica
I20260812 06:18:05.940198  4762 raft_consensus.cc:2243] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.940397  4762 raft_consensus.cc:2272] T 94fd95ca0dea4404843f8b493d467271 P e5c246eb75054d4787b23ca94f717925 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.945272  4762 tablet_server.cc:196] TabletServer@127.4.166.129:0 shutdown complete.
I20260812 06:18:05.990574  4762 master.cc:562] Master@127.4.166.190:35713 shutting down...
I20260812 06:18:05.994307  4762 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.994474  4762 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.994526  4762 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6baeaebe456e4928b072edf6a15c53e5: stopping tablet replica
I20260812 06:18:06.006847  4762 master.cc:584] Master@127.4.166.190:35713 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5334 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10569 ms total)

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