[==========] 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:18:02.399457 23503 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.243.254:41883
I20260812 06:18:02.400600 23503 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:18:02.401237 23503 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.408202 23512 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:02.408274 23503 server_base.cc:1061] running on GCE node
W20260812 06:18:02.408181 23509 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:02.408457 23510 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:02.408950 23503 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.409081 23503 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:02.409132 23503 hybrid_clock.cc:648] HybridClock initialized: now 1786515482409129 us; error 0 us; skew 500 ppm
I20260812 06:18:02.410985 23503 webserver.cc:533] Webserver started at http://127.22.243.254:38363/ using document root <none> and password file <none>
I20260812 06:18:02.411569 23503 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.411661 23503 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.411926 23503 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.413694 23503 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/master-0-root/instance:
uuid: "0063beceeeac4283966e1b1db42b9f0e"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1zqn"
I20260812 06:18:02.417292 23503 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:02.419454 23517 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:02.420524 23503 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:02.420672 23503 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/master-0-root
uuid: "0063beceeeac4283966e1b1db42b9f0e"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1zqn"
I20260812 06:18:02.420784 23503 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-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:02.433070 23503 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.433772 23503 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:18:02.433965 23503 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.442135 23503 rpc_server.cc:307] RPC server started. Bound to: 127.22.243.254:41883
I20260812 06:18:02.442139 23577 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.243.254:41883 every 8 connection(s)
I20260812 06:18:02.444689 23578 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:02.450309 23578 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: Bootstrap starting.
I20260812 06:18:02.452776 23578 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.453727 23578 log.cc:826] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:02.456032 23578 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: No bootstrap required, opened a new log
I20260812 06:18:02.459637 23578 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER }
I20260812 06:18:02.459820 23578 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.459870 23578 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0063beceeeac4283966e1b1db42b9f0e, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.460502 23578 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [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: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER }
I20260812 06:18:02.460652 23578 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.460701 23578 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.460798 23578 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.461594 23578 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER }
I20260812 06:18:02.462008 23578 leader_election.cc:304] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [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: 0063beceeeac4283966e1b1db42b9f0e; no voters: 
I20260812 06:18:02.462302 23578 leader_election.cc:290] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.462461 23582 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.462723 23582 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 1 LEADER]: Becoming Leader. State: Replica: 0063beceeeac4283966e1b1db42b9f0e, State: Running, Role: LEADER
I20260812 06:18:02.463199 23582 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [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: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER }
I20260812 06:18:02.463321 23578 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:02.465268 23584 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0063beceeeac4283966e1b1db42b9f0e. Latest consensus state: current_term: 1 leader_uuid: "0063beceeeac4283966e1b1db42b9f0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER } }
I20260812 06:18:02.465391 23584 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.465281 23583 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0063beceeeac4283966e1b1db42b9f0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0063beceeeac4283966e1b1db42b9f0e" member_type: VOTER } }
I20260812 06:18:02.465698 23583 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:02.466120 23503 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:02.468365 23599 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:02.468448 23599 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:02.468518 23597 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:02.469264 23597 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:02.474406 23597 catalog_manager.cc:1383] Generated new cluster ID: a2ae7a1fdcd944d985a26dd1eaf7318e
I20260812 06:18:02.474489 23597 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:02.489665 23597 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:02.490671 23597 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:02.500964 23597 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: Generated new TSK 0
I20260812 06:18:02.501719 23597 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:02.531340 23503 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.534324 23605 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:18:02.534349 23607 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:02.534356 23604 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:18:02.534786 23503 server_base.cc:1061] running on GCE node
I20260812 06:18:02.534957 23503 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.535012 23503 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:02.535130 23503 hybrid_clock.cc:648] HybridClock initialized: now 1786515482535128 us; error 0 us; skew 500 ppm
I20260812 06:18:02.536142 23503 webserver.cc:533] Webserver started at http://127.22.243.193:44543/ using document root <none> and password file <none>
I20260812 06:18:02.536334 23503 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.536402 23503 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.536557 23503 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.536991 23503 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/instance:
uuid: "c7ac272c1a8b4ac688d6763a3e81f97f"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1zqn"
I20260812 06:18:02.538856 23503 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:02.540131 23613 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:02.540454 23503 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:02.540530 23503 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root
uuid: "c7ac272c1a8b4ac688d6763a3e81f97f"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1zqn"
I20260812 06:18:02.540628 23503 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-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:02.550832 23503 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:02.551350 23503 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:02.551930 23503 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:02.552930 23503 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:02.552985 23503 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.553056 23503 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:02.553092 23503 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.560242 23503 rpc_server.cc:307] RPC server started. Bound to: 127.22.243.193:43251
I20260812 06:18:02.560258 23684 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.243.193:43251 every 8 connection(s)
I20260812 06:18:02.571177 23686 heartbeater.cc:344] Connected to a master server at 127.22.243.254:41883
I20260812 06:18:02.571456 23686 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:02.571938 23686 heartbeater.cc:507] Master 127.22.243.254:41883 requested a full tablet report, sending...
I20260812 06:18:02.573408 23536 ts_manager.cc:194] Registered new tserver with Master: c7ac272c1a8b4ac688d6763a3e81f97f (127.22.243.193:43251)
I20260812 06:18:02.573514 23503 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012574368s
I20260812 06:18:02.574647 23536 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48498
I20260812 06:18:02.583963 23536 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48506:
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:02.597972 23643 tablet_service.cc:1511] Processing CreateTablet for tablet c746ba248544482597b77aa542ba6286 (DEFAULT_TABLE table=heavy-update-compaction-test [id=58965fc12f544cb29a35cb081e8ce6ef]), partition=
I20260812 06:18:02.598456 23643 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c746ba248544482597b77aa542ba6286. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:02.601150 23699 tablet_bootstrap.cc:492] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Bootstrap starting.
I20260812 06:18:02.602820 23699 tablet_bootstrap.cc:654] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:02.604147 23699 tablet_bootstrap.cc:492] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: No bootstrap required, opened a new log
I20260812 06:18:02.604274 23699 ts_tablet_manager.cc:1403] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:02.604774 23699 raft_consensus.cc:359] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7ac272c1a8b4ac688d6763a3e81f97f" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 43251 } }
I20260812 06:18:02.604903 23699 raft_consensus.cc:385] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:02.604984 23699 raft_consensus.cc:740] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c7ac272c1a8b4ac688d6763a3e81f97f, State: Initialized, Role: FOLLOWER
I20260812 06:18:02.605145 23699 consensus_queue.cc:260] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [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: "c7ac272c1a8b4ac688d6763a3e81f97f" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 43251 } }
I20260812 06:18:02.605257 23699 raft_consensus.cc:399] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:02.605306 23699 raft_consensus.cc:493] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:02.605360 23699 raft_consensus.cc:3060] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:02.606567 23699 raft_consensus.cc:515] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7ac272c1a8b4ac688d6763a3e81f97f" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 43251 } }
I20260812 06:18:02.606724 23699 leader_election.cc:304] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [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: c7ac272c1a8b4ac688d6763a3e81f97f; no voters: 
I20260812 06:18:02.607012 23699 leader_election.cc:290] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:02.607132 23701 raft_consensus.cc:2804] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:02.607401 23701 raft_consensus.cc:697] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 1 LEADER]: Becoming Leader. State: Replica: c7ac272c1a8b4ac688d6763a3e81f97f, State: Running, Role: LEADER
I20260812 06:18:02.607648 23686 heartbeater.cc:499] Master 127.22.243.254:41883 was elected leader, sending a full tablet report...
I20260812 06:18:02.607620 23701 consensus_queue.cc:237] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [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: "c7ac272c1a8b4ac688d6763a3e81f97f" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 43251 } }
I20260812 06:18:02.607436 23699 ts_tablet_manager.cc:1434] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:02.610678 23536 catalog_manager.cc:5719] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f reported cstate change: term changed from 0 to 1, leader changed from <none> to c7ac272c1a8b4ac688d6763a3e81f97f (127.22.243.193). New cstate: current_term: 1 leader_uuid: "c7ac272c1a8b4ac688d6763a3e81f97f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7ac272c1a8b4ac688d6763a3e81f97f" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 43251 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:02.680766 23503 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.025s	sys 0.004s
I20260812 06:18:02.811674 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushMRSOp(c746ba248544482597b77aa542ba6286): perf score=15.086190
I20260812 06:18:02.966002 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushMRSOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.154s	user 0.113s	sys 0.038s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":259,"delete_count":0,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":2514,"drs_written":1,"lbm_read_time_us":114,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34894,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":173952,"thread_start_us":174,"threads_started":1,"update_count":1500}
I20260812 06:18:02.967180 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling LogGCOp(c746ba248544482597b77aa542ba6286): free 20743880 bytes of WAL
I20260812 06:18:02.967507 23619 log_reader.cc:385] T c746ba248544482597b77aa542ba6286: removed 2 log segments from log reader
I20260812 06:18:02.967582 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000001 (ops 1-6)
I20260812 06:18:02.967685 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000002 (ops 7-11)
I20260812 06:18:02.972224 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: LogGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:02.972601 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286): 12719213 bytes on disk
I20260812 06:18:02.973181 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.973591 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:02.994588 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.021s	user 0.005s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6549,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.995114 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:03.123914 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.129s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262023,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":758,"lbm_read_time_us":7747,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25484,"lbm_writes_lt_1ms":433,"mutex_wait_us":85,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":309,"threads_started":5,"update_count":1950}
I20260812 06:18:03.124512 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:03.173671 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.049s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16301,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.174186 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:03.186120 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.186735 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:03.318979 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.132s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":8850,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25315,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:03.319633 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:03.366314 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.046s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.366784 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:03.377671 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.378188 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:03.511054 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.133s	user 0.112s	sys 0.017s 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":749,"lbm_read_time_us":7841,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26184,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2000}
I20260812 06:18:03.511835 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:03.566617 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.055s	user 0.028s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16103,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.567226 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:03.578670 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.579121 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:03.728374 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.149s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1052,"lbm_read_time_us":11161,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25242,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.729033 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:03.777621 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.048s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18323,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.778131 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:03.790392 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.791255 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:03.919562 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":9973,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24680,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":77440,"update_count":2000}
I20260812 06:18:03.920379 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:03.960460 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.040s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16200,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.960978 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:03.972751 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.973402 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:04.100893 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.127s	user 0.107s	sys 0.020s 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":1506,"lbm_read_time_us":9414,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23265,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1210368,"update_count":2000}
I20260812 06:18:04.102169 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:04.145982 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14977,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.146566 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:04.157470 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.157938 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:04.318948 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.161s	user 0.128s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":958,"lbm_read_time_us":10601,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25873,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.319702 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:04.361768 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.042s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17539,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.362293 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:04.373325 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.373935 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushMRSOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:04.407784 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushMRSOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.034s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":341,"dirs.run_wall_time_us":1568,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1472,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:04.408655 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling LogGCOp(c746ba248544482597b77aa542ba6286): free 124710298 bytes of WAL
I20260812 06:18:04.408876 23619 log_reader.cc:385] T c746ba248544482597b77aa542ba6286: removed 12 log segments from log reader
I20260812 06:18:04.408913 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000003 (ops 12-16)
I20260812 06:18:04.408943 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000004 (ops 17-21)
I20260812 06:18:04.408996 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000005 (ops 22-26)
I20260812 06:18:04.409052 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000006 (ops 27-31)
I20260812 06:18:04.409097 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000007 (ops 32-36)
I20260812 06:18:04.409153 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000008 (ops 37-41)
I20260812 06:18:04.409190 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000009 (ops 42-46)
I20260812 06:18:04.409232 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000010 (ops 47-51)
I20260812 06:18:04.409271 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000011 (ops 52-56)
I20260812 06:18:04.409307 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000012 (ops 57-61)
I20260812 06:18:04.409344 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000013 (ops 62-66)
I20260812 06:18:04.409381 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000014 (ops 67-71)
I20260812 06:18:04.437552 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: LogGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:04.438019 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286): 483 bytes on disk
I20260812 06:18:04.438529 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.439106 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=3.181125
I20260812 06:18:04.466393 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.027s	user 0.009s	sys 0.015s Metrics: {"bytes_written":4841098,"delete_count":0,"lbm_write_time_us":7113,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:18:04.466915 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:04.476608 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":3513,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:18:04.477136 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:04.671561 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.194s	user 0.118s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":173,"lbm_read_time_us":13821,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33781,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:04.672483 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:04.713184 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.041s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19061,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.713757 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:04.734289 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.739758 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:04.920436 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.180s	user 0.120s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":690,"lbm_read_time_us":13100,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27811,"lbm_writes_lt_1ms":443,"mutex_wait_us":308,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:18:04.921118 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:04.957758 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.958294 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.084868 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.126s	user 0.091s	sys 0.035s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":46,"lbm_read_time_us":7501,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22168,"lbm_writes_lt_1ms":343,"mutex_wait_us":35,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":1500}
I20260812 06:18:05.088359 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=7.149875
I20260812 06:18:05.125348 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.037s	user 0.015s	sys 0.016s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13281,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:05.126041 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:05.145125 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6313,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.145833 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.283685 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.138s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":11717,"lbm_reads_lt_1ms":372,"lbm_write_time_us":20783,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:05.284451 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:05.316799 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.032s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13137,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.317358 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:05.332921 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.333560 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.456228 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.122s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":7659,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24472,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.457017 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:05.501267 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.044s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.501817 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:05.513147 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.513792 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.646687 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.133s	user 0.101s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2270,"lbm_read_time_us":9625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25133,"lbm_writes_lt_1ms":443,"mutex_wait_us":411,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:18:05.647516 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:05.695115 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.047s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18085,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.695647 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:05.707077 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.707612 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.835570 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.128s	user 0.099s	sys 0.028s 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":1577,"lbm_read_time_us":10168,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24091,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:05.836349 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:05.894261 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.058s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19998,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.895490 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.905943 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.010s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1312956,"delete_count":0,"lbm_write_time_us":1503,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:18:05.906474 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=1.196750
I20260812 06:18:05.917964 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:05.918538 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushMRSOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:05.964846 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushMRSOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.046s	user 0.024s	sys 0.009s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":32,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1684,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:05.965557 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling LogGCOp(c746ba248544482597b77aa542ba6286): free 120553340 bytes of WAL
I20260812 06:18:05.965811 23619 log_reader.cc:385] T c746ba248544482597b77aa542ba6286: removed 12 log segments from log reader
I20260812 06:18:05.965878 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000015 (ops 72-76)
I20260812 06:18:05.965934 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000016 (ops 77-81)
I20260812 06:18:05.965986 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000017 (ops 82-86)
I20260812 06:18:05.966025 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000018 (ops 87-91)
I20260812 06:18:05.966063 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000019 (ops 92-96)
I20260812 06:18:05.966101 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000020 (ops 97-100)
I20260812 06:18:05.966142 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000021 (ops 101-105)
I20260812 06:18:05.966185 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000022 (ops 106-110)
I20260812 06:18:05.966221 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000023 (ops 111-114)
I20260812 06:18:05.966259 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000024 (ops 115-119)
I20260812 06:18:05.966295 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000025 (ops 120-124)
I20260812 06:18:05.966333 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000026 (ops 125-129)
I20260812 06:18:05.993825 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: LogGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:05.994284 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286): 447 bytes on disk
I20260812 06:18:05.994920 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.995754 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:06.013581 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.014156 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:06.029377 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.029850 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:06.234592 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.205s	user 0.132s	sys 0.071s Metrics: {"cfile_cache_miss":635,"cfile_cache_miss_bytes":28877365,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":258,"lbm_read_time_us":14629,"lbm_reads_lt_1ms":675,"lbm_write_time_us":34338,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:06.236505 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=14.095187
I20260812 06:18:06.304257 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.068s	user 0.049s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23500,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.304822 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:06.320835 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.321440 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:06.510668 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.189s	user 0.133s	sys 0.046s 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":447,"lbm_read_time_us":13403,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31346,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:06.511299 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=14.095187
I20260812 06:18:06.572271 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.061s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.572847 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:06.590427 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.591076 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:06.777493 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.186s	user 0.129s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":12312,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32697,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":142464,"update_count":2500}
I20260812 06:18:06.778193 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=14.095187
I20260812 06:18:06.841640 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.063s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.842409 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:06.853837 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.854328 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:07.028679 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.174s	user 0.121s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":13781,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29208,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:18:07.029275 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=10.126437
I20260812 06:18:07.067814 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.038s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16937,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.068552 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:07.082906 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.083364 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:07.212327 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.129s	user 0.093s	sys 0.036s 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":96,"lbm_read_time_us":7999,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24268,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:18:07.215866 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=11.118625
I20260812 06:18:07.251368 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.035s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15412,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.252532 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:07.278708 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5314,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.279175 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:07.289933 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.290421 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:07.450671 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.159s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":997,"lbm_read_time_us":10097,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29909,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:18:07.451354 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=14.095187
I20260812 06:18:07.501375 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.050s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.502007 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:07.513896 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.514724 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushMRSOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:07.543311 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushMRSOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1378,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1817,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:07.543990 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling LogGCOp(c746ba248544482597b77aa542ba6286): free 120553697 bytes of WAL
I20260812 06:18:07.544269 23619 log_reader.cc:385] T c746ba248544482597b77aa542ba6286: removed 12 log segments from log reader
I20260812 06:18:07.544341 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000027 (ops 130-134)
I20260812 06:18:07.544381 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000028 (ops 135-139)
I20260812 06:18:07.544411 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000029 (ops 140-144)
I20260812 06:18:07.544438 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000030 (ops 145-149)
I20260812 06:18:07.544473 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000031 (ops 150-154)
I20260812 06:18:07.544507 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000032 (ops 155-159)
I20260812 06:18:07.544538 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000033 (ops 160-164)
I20260812 06:18:07.544564 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000034 (ops 165-168)
I20260812 06:18:07.544592 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000035 (ops 169-173)
I20260812 06:18:07.544633 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000036 (ops 174-178)
I20260812 06:18:07.544668 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000037 (ops 179-182)
I20260812 06:18:07.544697 23619 log.cc:1079] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/c746ba248544482597b77aa542ba6286/wal-000000038 (ops 183-187)
I20260812 06:18:07.575410 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: LogGCOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:07.575867 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286): 483 bytes on disk
I20260812 06:18:07.576356 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: UndoDeltaBlockGCOp(c746ba248544482597b77aa542ba6286) 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:07.576889 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=3.181125
I20260812 06:18:07.590019 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:07.590492 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=2.188937
I20260812 06:18:07.600411 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.600903 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286): perf score=1.000000
I20260812 06:18:07.812754 23503 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.132s	user 1.881s	sys 0.119s
I20260812 06:18:07.817267 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: MajorDeltaCompactionOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.216s	user 0.176s	sys 0.040s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1389,"lbm_read_time_us":14578,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45884,"lbm_writes_lt_1ms":743,"mutex_wait_us":702,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:07.818318 23687 maintenance_manager.cc:419] P c7ac272c1a8b4ac688d6763a3e81f97f: Scheduling FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286): perf score=14.095187
I20260812 06:18:07.847628 23503 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.034s	user 0.001s	sys 0.000s
I20260812 06:18:07.848423 23503 tablet_server.cc:179] TabletServer@127.22.243.193:0 shutting down...
I20260812 06:18:07.869632 23619 maintenance_manager.cc:643] P c7ac272c1a8b4ac688d6763a3e81f97f: FlushDeltaMemStoresOp(c746ba248544482597b77aa542ba6286) complete. Timing: real 0.051s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22879,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.870285 23503 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:07.870775 23503 tablet_replica.cc:333] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f: stopping tablet replica
I20260812 06:18:07.871044 23503 raft_consensus.cc:2243] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.871285 23503 raft_consensus.cc:2272] T c746ba248544482597b77aa542ba6286 P c7ac272c1a8b4ac688d6763a3e81f97f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.888298 23503 tablet_server.cc:196] TabletServer@127.22.243.193:0 shutdown complete.
I20260812 06:18:07.893687 23503 master.cc:562] Master@127.22.243.254:41883 shutting down...
I20260812 06:18:07.897720 23503 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.897933 23503 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.898023 23503 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0063beceeeac4283966e1b1db42b9f0e: stopping tablet replica
I20260812 06:18:07.910663 23503 master.cc:584] Master@127.22.243.254:41883 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5606 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:08.005113 23503 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.243.254:35095
I20260812 06:18:08.005539 23503 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.007784 23721 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:18:08.007892 23503 server_base.cc:1061] running on GCE node
W20260812 06:18:08.007813 23722 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:18:08.007967 23724 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:08.008306 23503 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.008369 23503 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:08.008395 23503 hybrid_clock.cc:648] HybridClock initialized: now 1786515488008394 us; error 0 us; skew 500 ppm
I20260812 06:18:08.009261 23503 webserver.cc:533] Webserver started at http://127.22.243.254:33025/ using document root <none> and password file <none>
I20260812 06:18:08.009481 23503 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.009557 23503 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.009639 23503 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.010054 23503 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/master-0-root/instance:
uuid: "ab029daf25334d3b84dd90fdde43369a"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1zqn"
I20260812 06:18:08.011656 23503 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:08.013036 23732 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:08.013330 23503 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.013411 23503 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/master-0-root
uuid: "ab029daf25334d3b84dd90fdde43369a"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1zqn"
I20260812 06:18:08.013475 23503 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-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:08.019994 23503 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.020427 23503 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.024421 23503 rpc_server.cc:307] RPC server started. Bound to: 127.22.243.254:35095
I20260812 06:18:08.026266 23791 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.243.254:35095 every 8 connection(s)
I20260812 06:18:08.030084 23793 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:08.042949 23793 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a: Bootstrap starting.
I20260812 06:18:08.043917 23793 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.045179 23793 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a: No bootstrap required, opened a new log
I20260812 06:18:08.045629 23793 raft_consensus.cc:359] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER }
I20260812 06:18:08.045727 23793 raft_consensus.cc:385] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.045750 23793 raft_consensus.cc:740] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ab029daf25334d3b84dd90fdde43369a, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.045938 23793 consensus_queue.cc:260] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [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: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER }
I20260812 06:18:08.046017 23793 raft_consensus.cc:399] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.046066 23793 raft_consensus.cc:493] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.046126 23793 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.046882 23793 raft_consensus.cc:515] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER }
I20260812 06:18:08.047035 23793 leader_election.cc:304] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [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: ab029daf25334d3b84dd90fdde43369a; no voters: 
I20260812 06:18:08.047261 23793 leader_election.cc:290] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.047410 23797 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.047645 23797 raft_consensus.cc:697] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 1 LEADER]: Becoming Leader. State: Replica: ab029daf25334d3b84dd90fdde43369a, State: Running, Role: LEADER
I20260812 06:18:08.047735 23793 sys_catalog.cc:565] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:08.047837 23797 consensus_queue.cc:237] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [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: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER }
I20260812 06:18:08.048414 23799 sys_catalog.cc:455] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [sys.catalog]: SysCatalogTable state changed. Reason: New leader ab029daf25334d3b84dd90fdde43369a. Latest consensus state: current_term: 1 leader_uuid: "ab029daf25334d3b84dd90fdde43369a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER } }
I20260812 06:18:08.048377 23798 sys_catalog.cc:455] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ab029daf25334d3b84dd90fdde43369a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ab029daf25334d3b84dd90fdde43369a" member_type: VOTER } }
I20260812 06:18:08.048491 23799 sys_catalog.cc:458] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.048501 23798 sys_catalog.cc:458] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.048832 23804 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:08.049695 23804 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:08.049870 23503 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:08.051543 23804 catalog_manager.cc:1383] Generated new cluster ID: dcc2f7f1c218471f99a91d0a4aa06487
I20260812 06:18:08.051604 23804 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:08.074415 23804 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:08.074990 23804 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:08.081121 23804 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a: Generated new TSK 0
I20260812 06:18:08.081313 23804 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:08.082334 23503 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.084376 23820 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:08.084368 23817 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:18:08.084545 23503 server_base.cc:1061] running on GCE node
W20260812 06:18:08.084376 23818 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:08.084789 23503 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.084834 23503 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:08.084851 23503 hybrid_clock.cc:648] HybridClock initialized: now 1786515488084850 us; error 0 us; skew 500 ppm
I20260812 06:18:08.085688 23503 webserver.cc:533] Webserver started at http://127.22.243.193:39143/ using document root <none> and password file <none>
I20260812 06:18:08.085878 23503 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.085943 23503 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.086030 23503 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.086470 23503 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/instance:
uuid: "d63e1afaddca4957aee03fb6344cb783"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1zqn"
I20260812 06:18:08.088258 23503 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:08.089237 23826 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:08.089531 23503 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.089620 23503 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root
uuid: "d63e1afaddca4957aee03fb6344cb783"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1zqn"
I20260812 06:18:08.089709 23503 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-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:08.095986 23503 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.096414 23503 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.096735 23503 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:08.097218 23503 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:08.097276 23503 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.097338 23503 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:08.097385 23503 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.101964 23503 rpc_server.cc:307] RPC server started. Bound to: 127.22.243.193:44907
I20260812 06:18:08.101994 23898 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.243.193:44907 every 8 connection(s)
I20260812 06:18:08.112975 23899 heartbeater.cc:344] Connected to a master server at 127.22.243.254:35095
I20260812 06:18:08.113163 23899 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:08.113507 23899 heartbeater.cc:507] Master 127.22.243.254:35095 requested a full tablet report, sending...
I20260812 06:18:08.114315 23751 ts_manager.cc:194] Registered new tserver with Master: d63e1afaddca4957aee03fb6344cb783 (127.22.243.193:44907)
I20260812 06:18:08.114670 23503 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012220761s
I20260812 06:18:08.115202 23751 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54694
I20260812 06:18:08.122265 23751 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54698:
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:08.131162 23857 tablet_service.cc:1511] Processing CreateTablet for tablet 00408e269a6b42cc9f68b3e07e4a9515 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b98dc48d1afe474da510c865bb05fa51]), partition=
I20260812 06:18:08.131502 23857 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00408e269a6b42cc9f68b3e07e4a9515. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.133846 23915 tablet_bootstrap.cc:492] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Bootstrap starting.
I20260812 06:18:08.134725 23915 tablet_bootstrap.cc:654] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.135823 23915 tablet_bootstrap.cc:492] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: No bootstrap required, opened a new log
I20260812 06:18:08.135939 23915 ts_tablet_manager.cc:1403] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:08.136433 23915 raft_consensus.cc:359] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63e1afaddca4957aee03fb6344cb783" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 44907 } }
I20260812 06:18:08.136546 23915 raft_consensus.cc:385] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.136598 23915 raft_consensus.cc:740] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d63e1afaddca4957aee03fb6344cb783, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.136747 23915 consensus_queue.cc:260] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [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: "d63e1afaddca4957aee03fb6344cb783" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 44907 } }
I20260812 06:18:08.136868 23915 raft_consensus.cc:399] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.136919 23915 raft_consensus.cc:493] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.136978 23915 raft_consensus.cc:3060] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.137717 23915 raft_consensus.cc:515] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63e1afaddca4957aee03fb6344cb783" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 44907 } }
I20260812 06:18:08.137880 23915 leader_election.cc:304] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [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: d63e1afaddca4957aee03fb6344cb783; no voters: 
I20260812 06:18:08.138101 23915 leader_election.cc:290] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.138228 23918 raft_consensus.cc:2804] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.138471 23918 raft_consensus.cc:697] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 1 LEADER]: Becoming Leader. State: Replica: d63e1afaddca4957aee03fb6344cb783, State: Running, Role: LEADER
I20260812 06:18:08.138474 23915 ts_tablet_manager.cc:1434] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:08.138501 23899 heartbeater.cc:499] Master 127.22.243.254:35095 was elected leader, sending a full tablet report...
I20260812 06:18:08.138650 23918 consensus_queue.cc:237] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [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: "d63e1afaddca4957aee03fb6344cb783" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 44907 } }
I20260812 06:18:08.140254 23751 catalog_manager.cc:5719] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 reported cstate change: term changed from 0 to 1, leader changed from <none> to d63e1afaddca4957aee03fb6344cb783 (127.22.243.193). New cstate: current_term: 1 leader_uuid: "d63e1afaddca4957aee03fb6344cb783" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63e1afaddca4957aee03fb6344cb783" member_type: VOTER last_known_addr { host: "127.22.243.193" port: 44907 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:08.201848 23503 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.015s	sys 0.008s
I20260812 06:18:08.352968 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=19.054940
I20260812 06:18:08.516808 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.163s	user 0.106s	sys 0.056s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":949,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45063,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:08.517519 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling LogGCOp(00408e269a6b42cc9f68b3e07e4a9515): free 20743880 bytes of WAL
I20260812 06:18:08.517755 23832 log_reader.cc:385] T 00408e269a6b42cc9f68b3e07e4a9515: removed 2 log segments from log reader
I20260812 06:18:08.517802 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000001 (ops 1-6)
I20260812 06:18:08.517835 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000002 (ops 7-11)
I20260812 06:18:08.523017 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: LogGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:08.523407 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515): 16411397 bytes on disk
I20260812 06:18:08.523972 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.524468 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:08.537282 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.537806 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:08.684656 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.147s	user 0.100s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":649,"lbm_read_time_us":10767,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25416,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":324,"threads_started":5,"update_count":2000}
I20260812 06:18:08.685344 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=11.118625
I20260812 06:18:08.722352 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.037s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16540,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:08.722826 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:08.734457 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.734931 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:08.934315 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.199s	user 0.125s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":9230,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32164,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:18:08.935788 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:09.041288 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.105s	user 0.069s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":42516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.042181 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:09.066274 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.067075 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:09.328951 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.261s	user 0.185s	sys 0.076s 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":914,"lbm_read_time_us":29240,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35634,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":196224,"update_count":2500}
I20260812 06:18:09.329681 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:09.394546 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.065s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23072,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.395270 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:09.407521 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.408000 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:09.598373 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.190s	user 0.126s	sys 0.060s 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":362,"lbm_read_time_us":14153,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29280,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:09.598953 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:09.657450 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.058s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29667,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.658001 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:09.681145 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.023s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.681782 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:09.868492 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.186s	user 0.149s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1116,"lbm_read_time_us":13516,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30635,"lbm_writes_lt_1ms":543,"mutex_wait_us":379,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:09.869037 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:09.920539 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.051s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20936,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.921075 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:09.932749 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.933370 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:09.975103 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.041s	user 0.029s	sys 0.010s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1502,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2272,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:09.975904 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling LogGCOp(00408e269a6b42cc9f68b3e07e4a9515): free 111786258 bytes of WAL
I20260812 06:18:09.976209 23832 log_reader.cc:385] T 00408e269a6b42cc9f68b3e07e4a9515: removed 11 log segments from log reader
I20260812 06:18:09.976259 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000003 (ops 12-16)
I20260812 06:18:09.976291 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000004 (ops 17-20)
I20260812 06:18:09.976354 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000005 (ops 21-25)
I20260812 06:18:09.976384 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000006 (ops 26-30)
I20260812 06:18:09.976428 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000007 (ops 31-35)
I20260812 06:18:09.976482 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000008 (ops 36-40)
I20260812 06:18:09.976521 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000009 (ops 41-44)
I20260812 06:18:09.976557 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000010 (ops 45-49)
I20260812 06:18:09.976593 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000011 (ops 50-54)
I20260812 06:18:09.976625 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000012 (ops 55-59)
I20260812 06:18:09.976652 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000013 (ops 60-64)
I20260812 06:18:10.002065 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: LogGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.026s	user 0.004s	sys 0.020s Metrics: {}
I20260812 06:18:10.002578 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515): 447 bytes on disk
I20260812 06:18:10.003062 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.003567 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:10.017951 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.018438 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:10.236671 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.218s	user 0.139s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":296,"lbm_read_time_us":15471,"lbm_reads_lt_1ms":669,"lbm_write_time_us":33377,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:18:10.237345 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=15.087375
I20260812 06:18:10.306864 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.069s	user 0.044s	sys 0.016s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23367,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:10.307626 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=3.181125
I20260812 06:18:10.325649 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4800070,"delete_count":0,"lbm_write_time_us":7065,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:18:10.326248 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.196750
I20260812 06:18:10.338568 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:18:10.339184 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:10.555800 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.216s	user 0.164s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":960,"lbm_read_time_us":14417,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37525,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:10.556550 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:10.599990 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19773,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.600698 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:10.612219 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.612751 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:10.813023 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.200s	user 0.144s	sys 0.048s 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":161,"lbm_read_time_us":14113,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33607,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:18:10.813719 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:10.888578 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.075s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":32647,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.889261 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:10.904795 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.905359 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:11.109084 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.204s	user 0.112s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":13140,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36701,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:11.109709 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:11.172425 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.063s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20428,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.173080 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:11.184228 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.184887 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:11.392910 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.208s	user 0.124s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":12779,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34222,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32512,"update_count":2500}
I20260812 06:18:11.393587 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:11.451736 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.058s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21802,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.452397 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:11.476011 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.023s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.476598 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:11.663290 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.186s	user 0.136s	sys 0.050s 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":727,"lbm_read_time_us":13554,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29380,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2500}
I20260812 06:18:11.663995 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:11.717624 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.053s	user 0.015s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23400,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.718117 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:11.729871 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.730472 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:11.772820 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.042s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1244,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1674,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:11.773492 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling LogGCOp(00408e269a6b42cc9f68b3e07e4a9515): free 129773565 bytes of WAL
I20260812 06:18:11.773746 23832 log_reader.cc:385] T 00408e269a6b42cc9f68b3e07e4a9515: removed 13 log segments from log reader
I20260812 06:18:11.773795 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000014 (ops 65-69)
I20260812 06:18:11.773824 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000015 (ops 70-74)
I20260812 06:18:11.773886 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000016 (ops 75-79)
I20260812 06:18:11.773931 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000017 (ops 80-84)
I20260812 06:18:11.773978 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000018 (ops 85-89)
I20260812 06:18:11.774021 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000019 (ops 90-94)
I20260812 06:18:11.774118 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000020 (ops 95-99)
I20260812 06:18:11.774140 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000021 (ops 100-104)
I20260812 06:18:11.774199 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000022 (ops 105-109)
I20260812 06:18:11.774241 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000023 (ops 110-114)
I20260812 06:18:11.774281 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000024 (ops 115-118)
I20260812 06:18:11.774320 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000025 (ops 119-123)
I20260812 06:18:11.774359 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000026 (ops 124-128)
I20260812 06:18:11.805220 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: LogGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:11.805675 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515): 493 bytes on disk
I20260812 06:18:11.806133 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:11.806828 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=3.181125
I20260812 06:18:11.821918 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4762,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:11.822366 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:11.832602 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.833109 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:12.112355 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.279s	user 0.170s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1549,"lbm_read_time_us":16624,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45723,"lbm_writes_lt_1ms":743,"mutex_wait_us":769,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:18:12.113236 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=18.063937
I20260812 06:18:12.179329 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.066s	user 0.050s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27630,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:12.179872 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:12.191470 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.192233 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:12.397032 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.205s	user 0.120s	sys 0.084s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":14033,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33630,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3000}
I20260812 06:18:12.397840 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:12.442766 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20144,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.443328 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:12.454545 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4414,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.455034 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:12.642804 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.188s	user 0.141s	sys 0.044s 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":246,"lbm_read_time_us":13496,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32264,"lbm_writes_lt_1ms":543,"mutex_wait_us":96,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:18:12.643572 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=11.118625
I20260812 06:18:12.691797 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.048s	user 0.030s	sys 0.014s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15852,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:12.692363 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:12.707351 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5358,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.707975 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:12.876890 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.169s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":9604,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26592,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:12.877488 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:12.927903 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.050s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.928574 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:12.945044 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.945694 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:13.104466 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.159s	user 0.109s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":9955,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31092,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:13.105365 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=11.118625
I20260812 06:18:13.144721 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.039s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17363,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:13.145291 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:13.158607 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5045,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.159190 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:13.286871 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.127s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":9754,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24461,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:13.287473 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=10.126437
I20260812 06:18:13.332682 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.045s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.333184 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:13.344712 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.345352 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:13.380028 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushMRSOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1699,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1991,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:13.380832 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling LogGCOp(00408e269a6b42cc9f68b3e07e4a9515): free 124257501 bytes of WAL
I20260812 06:18:13.381068 23832 log_reader.cc:385] T 00408e269a6b42cc9f68b3e07e4a9515: removed 12 log segments from log reader
I20260812 06:18:13.381119 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000027 (ops 129-133)
I20260812 06:18:13.381147 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000028 (ops 134-138)
I20260812 06:18:13.381189 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000029 (ops 139-143)
I20260812 06:18:13.381233 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000030 (ops 144-148)
I20260812 06:18:13.381281 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000031 (ops 149-153)
I20260812 06:18:13.381323 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000032 (ops 154-158)
I20260812 06:18:13.381369 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000033 (ops 159-162)
I20260812 06:18:13.381409 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000034 (ops 163-167)
I20260812 06:18:13.381448 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000035 (ops 168-172)
I20260812 06:18:13.381488 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000036 (ops 173-177)
I20260812 06:18:13.381531 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000037 (ops 178-182)
I20260812 06:18:13.381572 23832 log.cc:1079] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: Deleting log segment in path: /tmp/dist-test-taskc3fkqg/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482388451-23503-0/minicluster-data/ts-0-root/wals/00408e269a6b42cc9f68b3e07e4a9515/wal-000000038 (ops 183-187)
I20260812 06:18:13.408345 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: LogGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.027s	user 0.002s	sys 0.025s Metrics: {}
I20260812 06:18:13.408766 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515): 472 bytes on disk
I20260812 06:18:13.409212 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: UndoDeltaBlockGCOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.409782 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=3.181125
I20260812 06:18:13.422770 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4815,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:13.423398 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=2.188937
I20260812 06:18:13.437602 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:13.438288 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=1.000000
I20260812 06:18:13.629802 23503 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.428s	user 1.866s	sys 0.267s
I20260812 06:18:13.635301 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: MajorDeltaCompactionOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.197s	user 0.128s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":741,"lbm_read_time_us":15169,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39939,"lbm_writes_lt_1ms":643,"mutex_wait_us":96,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":108,"threads_started":1,"update_count":3000}
I20260812 06:18:13.636932 23900 maintenance_manager.cc:419] P d63e1afaddca4957aee03fb6344cb783: Scheduling FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515): perf score=14.095187
I20260812 06:18:13.659592 23503 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.029s	user 0.001s	sys 0.000s
I20260812 06:18:13.660202 23503 tablet_server.cc:179] TabletServer@127.22.243.193:0 shutting down...
I20260812 06:18:13.697979 23832 maintenance_manager.cc:643] P d63e1afaddca4957aee03fb6344cb783: FlushDeltaMemStoresOp(00408e269a6b42cc9f68b3e07e4a9515) complete. Timing: real 0.061s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28430,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.698573 23503 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:13.698817 23503 tablet_replica.cc:333] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783: stopping tablet replica
I20260812 06:18:13.698987 23503 raft_consensus.cc:2243] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.699180 23503 raft_consensus.cc:2272] T 00408e269a6b42cc9f68b3e07e4a9515 P d63e1afaddca4957aee03fb6344cb783 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.713092 23503 tablet_server.cc:196] TabletServer@127.22.243.193:0 shutdown complete.
I20260812 06:18:13.716351 23503 master.cc:562] Master@127.22.243.254:35095 shutting down...
I20260812 06:18:13.719614 23503 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.719779 23503 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.719828 23503 tablet_replica.cc:333] T 00000000000000000000000000000000 P ab029daf25334d3b84dd90fdde43369a: stopping tablet replica
I20260812 06:18:13.732331 23503 master.cc:584] Master@127.22.243.254:35095 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5821 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11429 ms total)

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