[==========] 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:33.023388 22507 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.250.254:34529
I20260812 06:18:33.024606 22507 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:33.025314 22507 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:33.032368 22507 server_base.cc:1061] running on GCE node
W20260812 06:18:33.032382 22512 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:33.032534 22515 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:33.032739 22513 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:33.033316 22507 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.033468 22507 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:33.033517 22507 hybrid_clock.cc:648] HybridClock initialized: now 1786515513033513 us; error 0 us; skew 500 ppm
I20260812 06:18:33.035492 22507 webserver.cc:533] Webserver started at http://127.21.250.254:37979/ using document root <none> and password file <none>
I20260812 06:18:33.036113 22507 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.036207 22507 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.036489 22507 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.038297 22507 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/master-0-root/instance:
uuid: "e813ee5dd5f64c1fa772c55358ceb1a7"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-srgv"
I20260812 06:18:33.042037 22507 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:33.044272 22520 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:33.045499 22507 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.045647 22507 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/master-0-root
uuid: "e813ee5dd5f64c1fa772c55358ceb1a7"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-srgv"
I20260812 06:18:33.045764 22507 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-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:33.054838 22507 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.055497 22507 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:33.055701 22507 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.063891 22507 rpc_server.cc:307] RPC server started. Bound to: 127.21.250.254:34529
I20260812 06:18:33.063897 22577 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.250.254:34529 every 8 connection(s)
I20260812 06:18:33.066339 22578 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:33.072118 22578 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: Bootstrap starting.
I20260812 06:18:33.074678 22578 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.075656 22578 log.cc:826] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:33.077579 22578 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: No bootstrap required, opened a new log
I20260812 06:18:33.080428 22578 raft_consensus.cc:359] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER }
I20260812 06:18:33.080600 22578 raft_consensus.cc:385] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.080653 22578 raft_consensus.cc:740] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e813ee5dd5f64c1fa772c55358ceb1a7, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.081207 22578 consensus_queue.cc:260] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [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: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER }
I20260812 06:18:33.081344 22578 raft_consensus.cc:399] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.081391 22578 raft_consensus.cc:493] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.081566 22578 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.082347 22578 raft_consensus.cc:515] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER }
I20260812 06:18:33.082770 22578 leader_election.cc:304] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [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: e813ee5dd5f64c1fa772c55358ceb1a7; no voters: 
I20260812 06:18:33.083050 22578 leader_election.cc:290] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.083210 22581 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.083478 22581 raft_consensus.cc:697] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 1 LEADER]: Becoming Leader. State: Replica: e813ee5dd5f64c1fa772c55358ceb1a7, State: Running, Role: LEADER
I20260812 06:18:33.083935 22581 consensus_queue.cc:237] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [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: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER }
I20260812 06:18:33.084182 22578 sys_catalog.cc:565] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.085844 22583 sys_catalog.cc:455] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e813ee5dd5f64c1fa772c55358ceb1a7. Latest consensus state: current_term: 1 leader_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER } }
I20260812 06:18:33.085894 22582 sys_catalog.cc:455] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e813ee5dd5f64c1fa772c55358ceb1a7" member_type: VOTER } }
I20260812 06:18:33.085988 22583 sys_catalog.cc:458] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.085992 22582 sys_catalog.cc:458] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.086719 22507 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:33.088783 22596 catalog_manager.cc:1594] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:33.088861 22596 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:33.088917 22592 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.089834 22592 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.094861 22592 catalog_manager.cc:1383] Generated new cluster ID: 72a302c0dd914c5491bd405314d4c2e9
I20260812 06:18:33.094939 22592 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.115999 22592 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.116918 22592 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.126787 22592 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: Generated new TSK 0
I20260812 06:18:33.127456 22592 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.151507 22507 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.154377 22603 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:33.154386 22601 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:33.154474 22507 server_base.cc:1061] running on GCE node
W20260812 06:18:33.154386 22600 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:33.154850 22507 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.154914 22507 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:33.154942 22507 hybrid_clock.cc:648] HybridClock initialized: now 1786515513154940 us; error 0 us; skew 500 ppm
I20260812 06:18:33.156087 22507 webserver.cc:533] Webserver started at http://127.21.250.193:37965/ using document root <none> and password file <none>
I20260812 06:18:33.156280 22507 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.156353 22507 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.156435 22507 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.156844 22507 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/instance:
uuid: "16b80a7b4195470d80dee2561c8a1963"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-srgv"
I20260812 06:18:33.158567 22507 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:33.159592 22608 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:33.159837 22507 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.159911 22507 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root
uuid: "16b80a7b4195470d80dee2561c8a1963"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-srgv"
I20260812 06:18:33.160002 22507 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-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:33.164958 22507 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.165382 22507 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.165966 22507 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.166836 22507 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.166889 22507 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.166958 22507 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.166997 22507 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.173840 22507 rpc_server.cc:307] RPC server started. Bound to: 127.21.250.193:41249
I20260812 06:18:33.174041 22675 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.250.193:41249 every 8 connection(s)
I20260812 06:18:33.184412 22676 heartbeater.cc:344] Connected to a master server at 127.21.250.254:34529
I20260812 06:18:33.184686 22676 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.185145 22676 heartbeater.cc:507] Master 127.21.250.254:34529 requested a full tablet report, sending...
I20260812 06:18:33.186709 22539 ts_manager.cc:194] Registered new tserver with Master: 16b80a7b4195470d80dee2561c8a1963 (127.21.250.193:41249)
I20260812 06:18:33.186889 22507 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0123242s
I20260812 06:18:33.188238 22539 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46624
I20260812 06:18:33.196489 22539 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46636:
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:33.210832 22639 tablet_service.cc:1511] Processing CreateTablet for tablet a6e798909bc24b279c90b09fb6fd9cf4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3cc0765a90b144c09f30c5fcef5382a4]), partition=
I20260812 06:18:33.211380 22639 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a6e798909bc24b279c90b09fb6fd9cf4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.213680 22688 tablet_bootstrap.cc:492] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Bootstrap starting.
I20260812 06:18:33.214970 22688 tablet_bootstrap.cc:654] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.216109 22688 tablet_bootstrap.cc:492] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: No bootstrap required, opened a new log
I20260812 06:18:33.216236 22688 ts_tablet_manager.cc:1403] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:33.216682 22688 raft_consensus.cc:359] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16b80a7b4195470d80dee2561c8a1963" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 41249 } }
I20260812 06:18:33.216805 22688 raft_consensus.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.216853 22688 raft_consensus.cc:740] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 16b80a7b4195470d80dee2561c8a1963, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.216998 22688 consensus_queue.cc:260] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [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: "16b80a7b4195470d80dee2561c8a1963" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 41249 } }
I20260812 06:18:33.217090 22688 raft_consensus.cc:399] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.217140 22688 raft_consensus.cc:493] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.217193 22688 raft_consensus.cc:3060] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.218008 22688 raft_consensus.cc:515] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16b80a7b4195470d80dee2561c8a1963" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 41249 } }
I20260812 06:18:33.218185 22688 leader_election.cc:304] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [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: 16b80a7b4195470d80dee2561c8a1963; no voters: 
I20260812 06:18:33.218391 22688 leader_election.cc:290] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.218688 22691 raft_consensus.cc:2804] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.218765 22688 ts_tablet_manager.cc:1434] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.218906 22691 raft_consensus.cc:697] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 1 LEADER]: Becoming Leader. State: Replica: 16b80a7b4195470d80dee2561c8a1963, State: Running, Role: LEADER
I20260812 06:18:33.219121 22691 consensus_queue.cc:237] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [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: "16b80a7b4195470d80dee2561c8a1963" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 41249 } }
I20260812 06:18:33.219269 22676 heartbeater.cc:499] Master 127.21.250.254:34529 was elected leader, sending a full tablet report...
I20260812 06:18:33.221864 22539 catalog_manager.cc:5719] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 reported cstate change: term changed from 0 to 1, leader changed from <none> to 16b80a7b4195470d80dee2561c8a1963 (127.21.250.193). New cstate: current_term: 1 leader_uuid: "16b80a7b4195470d80dee2561c8a1963" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "16b80a7b4195470d80dee2561c8a1963" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 41249 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:33.290614 22507 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.024s	sys 0.004s
I20260812 06:18:33.425239 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=15.086190
I20260812 06:18:33.615837 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.190s	user 0.140s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":442,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":724,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47831,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":2304,"thread_start_us":125,"threads_started":1,"update_count":1500}
I20260812 06:18:33.617038 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4): free 20743880 bytes of WAL
I20260812 06:18:33.617529 22613 log_reader.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4: removed 2 log segments from log reader
I20260812 06:18:33.617633 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000001 (ops 1-6)
I20260812 06:18:33.617717 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000002 (ops 7-11)
I20260812 06:18:33.623262 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:33.623754 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4): 16411571 bytes on disk
I20260812 06:18:33.624571 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":184,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.625078 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=3.181125
I20260812 06:18:33.654096 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.029s	user 0.015s	sys 0.010s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6873,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:33.654654 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:33.669175 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.669816 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:33.843683 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.174s	user 0.109s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":608,"lbm_read_time_us":13014,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28175,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":320,"threads_started":5,"update_count":2500}
I20260812 06:18:33.844336 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:33.888670 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.044s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16810,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.889171 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:33.899951 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.900425 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.037034 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.136s	user 0.113s	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":862,"lbm_read_time_us":9258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28598,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":88064,"update_count":2000}
I20260812 06:18:34.037803 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:34.079233 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.041s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15285,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.079766 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:34.095788 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.096431 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.231361 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.135s	user 0.097s	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":850,"lbm_read_time_us":8831,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29178,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:18:34.231951 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:34.275236 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.043s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15173,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.275810 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:34.287750 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.288305 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.416244 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.128s	user 0.084s	sys 0.040s 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":1335,"lbm_read_time_us":7848,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24381,"lbm_writes_lt_1ms":443,"mutex_wait_us":353,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:34.417006 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:34.462285 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.045s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15360,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.462894 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:34.473922 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.474418 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.623945 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.149s	user 0.109s	sys 0.040s 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":362,"lbm_read_time_us":11124,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29117,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":47104,"update_count":2000}
I20260812 06:18:34.624740 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:34.677811 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.053s	user 0.022s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":28411,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.678373 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:34.691172 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.691656 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.843333 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.151s	user 0.099s	sys 0.052s 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":771,"lbm_read_time_us":9434,"lbm_reads_lt_1ms":472,"lbm_write_time_us":40878,"lbm_writes_lt_1ms":443,"mutex_wait_us":170,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:34.844085 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:34.886987 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.043s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20236,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.887579 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:34.900653 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.901237 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:34.933655 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.032s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1342,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1560,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:34.934485 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4): free 115943174 bytes of WAL
I20260812 06:18:34.934739 22613 log_reader.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4: removed 11 log segments from log reader
I20260812 06:18:34.934784 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000003 (ops 12-16)
I20260812 06:18:34.934815 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000004 (ops 17-21)
I20260812 06:18:34.934876 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000005 (ops 22-26)
I20260812 06:18:34.934940 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000006 (ops 27-31)
I20260812 06:18:34.934986 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000007 (ops 32-36)
I20260812 06:18:34.935043 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000008 (ops 37-41)
I20260812 06:18:34.935102 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000009 (ops 42-46)
I20260812 06:18:34.935143 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000010 (ops 47-51)
I20260812 06:18:34.935181 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000011 (ops 52-56)
I20260812 06:18:34.935223 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000012 (ops 57-61)
I20260812 06:18:34.935259 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000013 (ops 62-66)
I20260812 06:18:34.961851 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.027s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:18:34.962272 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=3.181125
I20260812 06:18:34.975937 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":131,"mutex_wait_us":77,"reinsert_count":0,"update_count":640}
I20260812 06:18:34.976423 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.196750
I20260812 06:18:34.986716 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3258,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:34.987143 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4): 462 bytes on disk
I20260812 06:18:34.987623 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.988193 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:35.167089 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.179s	user 0.121s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":298,"lbm_read_time_us":11641,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35364,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:18:35.168097 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=14.095187
I20260812 06:18:35.218128 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.049s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19607,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.218639 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:35.230113 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.230820 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:35.388810 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.158s	user 0.115s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":422,"lbm_read_time_us":9555,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31592,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:35.389398 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=12.110812
I20260812 06:18:35.435267 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.046s	user 0.031s	sys 0.013s Metrics: {"bytes_written":13702336,"delete_count":0,"lbm_write_time_us":20922,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1670}
I20260812 06:18:35.435734 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.196750
I20260812 06:18:35.456187 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.020s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3285,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:18:35.456722 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:35.470304 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.013s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5189,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.470840 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:35.668766 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.198s	user 0.141s	sys 0.050s 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":353,"lbm_read_time_us":13680,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35176,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:35.669309 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=14.095187
I20260812 06:18:35.728303 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.059s	user 0.015s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24428,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.728899 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:35.740038 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.740816 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:35.907925 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.167s	user 0.128s	sys 0.031s 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":745,"lbm_read_time_us":10908,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29258,"lbm_writes_lt_1ms":543,"mutex_wait_us":258,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:35.908571 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=14.095187
I20260812 06:18:35.970638 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.062s	user 0.034s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25781,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.971235 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:35.981985 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.982452 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:36.153604 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.171s	user 0.120s	sys 0.050s 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":184,"lbm_read_time_us":13788,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28184,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:36.154182 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=11.118625
I20260812 06:18:36.190900 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.037s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15648,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.191502 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:36.212725 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5257,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.213295 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:36.362609 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.149s	user 0.112s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":9660,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24911,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:36.363276 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:36.397850 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.034s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15156,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.398386 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:36.408627 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.409070 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:36.441324 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1421,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2268,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:36.442087 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4): free 121006447 bytes of WAL
I20260812 06:18:36.442325 22613 log_reader.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4: removed 12 log segments from log reader
I20260812 06:18:36.442368 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000014 (ops 67-71)
I20260812 06:18:36.442397 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000015 (ops 72-76)
I20260812 06:18:36.442466 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000016 (ops 77-81)
I20260812 06:18:36.442497 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000017 (ops 82-86)
I20260812 06:18:36.442535 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000018 (ops 87-90)
I20260812 06:18:36.442579 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000019 (ops 91-95)
I20260812 06:18:36.442613 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000020 (ops 96-100)
I20260812 06:18:36.442651 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000021 (ops 101-105)
I20260812 06:18:36.442689 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000022 (ops 106-110)
I20260812 06:18:36.442727 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000023 (ops 111-115)
I20260812 06:18:36.442766 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000024 (ops 116-120)
I20260812 06:18:36.442804 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000025 (ops 121-125)
I20260812 06:18:36.469622 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.027s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:36.470081 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4): 472 bytes on disk
I20260812 06:18:36.470706 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.471194 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:36.485769 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.486268 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4): free 12017940 bytes of WAL
I20260812 06:18:36.486481 22613 log_reader.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4: removed 1 log segments from log reader
I20260812 06:18:36.486523 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000026 (ops 126-130)
I20260812 06:18:36.488912 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.489244 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:36.501571 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.502040 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:36.700047 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.198s	user 0.127s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":719,"lbm_read_time_us":11456,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36727,"lbm_writes_lt_1ms":643,"mutex_wait_us":549,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:36.700896 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=14.095187
I20260812 06:18:36.755467 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.054s	user 0.045s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24478,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.756037 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:36.767868 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.768378 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:36.951931 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.183s	user 0.122s	sys 0.052s 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":386,"lbm_read_time_us":11541,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33183,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:36.952721 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=11.118625
I20260812 06:18:36.992092 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16760,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.992699 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.011551 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5604,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.012118 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.141624 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.129s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":7567,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25474,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:37.142360 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=11.118625
I20260812 06:18:37.178069 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15253,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:37.178855 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.192261 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.192874 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.330724 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.138s	user 0.117s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":8772,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27608,"lbm_writes_lt_1ms":443,"mutex_wait_us":13,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:18:37.331656 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:37.377333 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.045s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307520,"delete_count":0,"lbm_write_time_us":16307,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.377977 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.389292 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.389892 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.537863 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.148s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672307,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":10761,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24594,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:37.538552 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:37.577317 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.039s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.577872 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.592235 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.592852 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.716846 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":7923,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25798,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:18:37.717733 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:37.755785 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.038s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15686,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.756336 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.770193 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.770741 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.906327 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.135s	user 0.107s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":9584,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26505,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:37.907017 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=10.126437
I20260812 06:18:37.952211 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.045s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15137,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.952836 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:37.967597 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.968101 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:37.999864 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushMRSOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.032s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1436,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1445,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:38.000547 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4): free 120553638 bytes of WAL
I20260812 06:18:38.000789 22613 log_reader.cc:385] T a6e798909bc24b279c90b09fb6fd9cf4: removed 12 log segments from log reader
I20260812 06:18:38.000833 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000027 (ops 131-135)
I20260812 06:18:38.000862 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000028 (ops 136-140)
I20260812 06:18:38.000933 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000029 (ops 141-144)
I20260812 06:18:38.000978 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000030 (ops 145-149)
I20260812 06:18:38.001015 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000031 (ops 150-154)
I20260812 06:18:38.001056 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000032 (ops 155-159)
I20260812 06:18:38.001096 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000033 (ops 160-164)
I20260812 06:18:38.001134 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000034 (ops 165-169)
I20260812 06:18:38.001173 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000035 (ops 170-174)
I20260812 06:18:38.001211 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000036 (ops 175-179)
I20260812 06:18:38.001260 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000037 (ops 180-184)
I20260812 06:18:38.001299 22613 log.cc:1079] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/a6e798909bc24b279c90b09fb6fd9cf4/wal-000000038 (ops 185-188)
I20260812 06:18:38.027455 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: LogGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:38.029333 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4): 483 bytes on disk
I20260812 06:18:38.029815 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: UndoDeltaBlockGCOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.030373 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=3.181125
I20260812 06:18:38.042685 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4843,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:38.043171 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=2.188937
I20260812 06:18:38.054486 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.056151 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=1.000000
I20260812 06:18:38.240070 22507 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.949s	user 1.849s	sys 0.115s
I20260812 06:18:38.243513 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: MajorDeltaCompactionOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.187s	user 0.156s	sys 0.026s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1223,"lbm_read_time_us":13148,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37106,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:38.244266 22677 maintenance_manager.cc:419] P 16b80a7b4195470d80dee2561c8a1963: Scheduling FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4): perf score=14.095187
I20260812 06:18:38.273918 22507 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.005s	sys 0.000s
I20260812 06:18:38.274796 22507 tablet_server.cc:179] TabletServer@127.21.250.193:0 shutting down...
I20260812 06:18:38.291436 22613 maintenance_manager.cc:643] P 16b80a7b4195470d80dee2561c8a1963: FlushDeltaMemStoresOp(a6e798909bc24b279c90b09fb6fd9cf4) complete. Timing: real 0.045s	user 0.014s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.292268 22507 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.292721 22507 tablet_replica.cc:333] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963: stopping tablet replica
I20260812 06:18:38.292989 22507 raft_consensus.cc:2243] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.293239 22507 raft_consensus.cc:2272] T a6e798909bc24b279c90b09fb6fd9cf4 P 16b80a7b4195470d80dee2561c8a1963 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.308611 22507 tablet_server.cc:196] TabletServer@127.21.250.193:0 shutdown complete.
I20260812 06:18:38.313997 22507 master.cc:562] Master@127.21.250.254:34529 shutting down...
I20260812 06:18:38.318018 22507 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.318218 22507 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.318274 22507 tablet_replica.cc:333] T 00000000000000000000000000000000 P e813ee5dd5f64c1fa772c55358ceb1a7: stopping tablet replica
I20260812 06:18:38.330895 22507 master.cc:584] Master@127.21.250.254:34529 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5399 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:38.421595 22507 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.250.254:34291
I20260812 06:18:38.422026 22507 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:38.424175 22710 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:38.424309 22709 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:38.424332 22712 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:38.424321 22507 server_base.cc:1061] running on GCE node
I20260812 06:18:38.424717 22507 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.424784 22507 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:38.424810 22507 hybrid_clock.cc:648] HybridClock initialized: now 1786515518424809 us; error 0 us; skew 500 ppm
I20260812 06:18:38.425806 22507 webserver.cc:533] Webserver started at http://127.21.250.254:37963/ using document root <none> and password file <none>
I20260812 06:18:38.426004 22507 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.426119 22507 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.426235 22507 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.426687 22507 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/master-0-root/instance:
uuid: "2363443400a44a3491fcced1ac01ec94"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-srgv"
I20260812 06:18:38.428290 22507 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:38.429308 22717 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:38.429669 22507 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:38.429768 22507 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/master-0-root
uuid: "2363443400a44a3491fcced1ac01ec94"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-srgv"
I20260812 06:18:38.429859 22507 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-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:38.449599 22507 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.450063 22507 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.454630 22507 rpc_server.cc:307] RPC server started. Bound to: 127.21.250.254:34291
I20260812 06:18:38.458298 22771 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.250.254:34291 every 8 connection(s)
I20260812 06:18:38.461462 22772 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:38.471654 22772 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94: Bootstrap starting.
I20260812 06:18:38.472600 22772 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.473883 22772 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94: No bootstrap required, opened a new log
I20260812 06:18:38.474400 22772 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER }
I20260812 06:18:38.474507 22772 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.474538 22772 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2363443400a44a3491fcced1ac01ec94, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.474761 22772 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [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: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER }
I20260812 06:18:38.474844 22772 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.474889 22772 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.474958 22772 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.475812 22772 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER }
I20260812 06:18:38.475941 22772 leader_election.cc:304] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [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: 2363443400a44a3491fcced1ac01ec94; no voters: 
I20260812 06:18:38.476308 22772 leader_election.cc:290] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.476543 22775 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.476779 22775 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 1 LEADER]: Becoming Leader. State: Replica: 2363443400a44a3491fcced1ac01ec94, State: Running, Role: LEADER
I20260812 06:18:38.476927 22772 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:38.476981 22775 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [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: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER }
I20260812 06:18:38.477665 22777 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2363443400a44a3491fcced1ac01ec94. Latest consensus state: current_term: 1 leader_uuid: "2363443400a44a3491fcced1ac01ec94" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER } }
I20260812 06:18:38.477792 22777 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.477964 22776 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2363443400a44a3491fcced1ac01ec94" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2363443400a44a3491fcced1ac01ec94" member_type: VOTER } }
I20260812 06:18:38.478091 22776 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.478411 22784 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:38.479220 22784 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:38.479405 22507 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:38.481240 22784 catalog_manager.cc:1383] Generated new cluster ID: fef253cb5b6f436eba71b1e3684304f0
I20260812 06:18:38.481315 22784 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:38.497993 22784 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:38.498623 22784 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:38.509764 22784 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94: Generated new TSK 0
I20260812 06:18:38.509999 22784 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:38.511890 22507 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:38.513947 22795 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:38.514047 22794 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:38.514081 22797 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:38.514256 22507 server_base.cc:1061] running on GCE node
I20260812 06:18:38.514413 22507 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.514451 22507 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:38.514468 22507 hybrid_clock.cc:648] HybridClock initialized: now 1786515518514468 us; error 0 us; skew 500 ppm
I20260812 06:18:38.515311 22507 webserver.cc:533] Webserver started at http://127.21.250.193:40173/ using document root <none> and password file <none>
I20260812 06:18:38.515447 22507 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.515496 22507 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.515549 22507 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.515919 22507 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/instance:
uuid: "00eb7526e88b46c99d181f5609c09baf"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-srgv"
I20260812 06:18:38.517586 22507 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:38.518603 22803 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:38.518879 22507 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:38.518949 22507 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root
uuid: "00eb7526e88b46c99d181f5609c09baf"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-srgv"
I20260812 06:18:38.519011 22507 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-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:38.524459 22507 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.524842 22507 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.525192 22507 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:38.525766 22507 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:38.525831 22507 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.525914 22507 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:38.525966 22507 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.530599 22507 rpc_server.cc:307] RPC server started. Bound to: 127.21.250.193:36215
I20260812 06:18:38.530681 22868 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.250.193:36215 every 8 connection(s)
I20260812 06:18:38.539985 22869 heartbeater.cc:344] Connected to a master server at 127.21.250.254:34291
I20260812 06:18:38.540160 22869 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:38.540432 22869 heartbeater.cc:507] Master 127.21.250.254:34291 requested a full tablet report, sending...
I20260812 06:18:38.541133 22734 ts_manager.cc:194] Registered new tserver with Master: 00eb7526e88b46c99d181f5609c09baf (127.21.250.193:36215)
I20260812 06:18:38.541222 22507 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010316185s
I20260812 06:18:38.542188 22734 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48528
I20260812 06:18:38.550094 22734 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48532:
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:38.559952 22831 tablet_service.cc:1511] Processing CreateTablet for tablet 6128a0e8c06046f4b3c88ffe5613aa50 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4fedfe9d1ffd41beb9dc7721fdd997bf]), partition=
I20260812 06:18:38.560290 22831 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6128a0e8c06046f4b3c88ffe5613aa50. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:38.562688 22883 tablet_bootstrap.cc:492] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Bootstrap starting.
I20260812 06:18:38.563643 22883 tablet_bootstrap.cc:654] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.564802 22883 tablet_bootstrap.cc:492] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: No bootstrap required, opened a new log
I20260812 06:18:38.564919 22883 ts_tablet_manager.cc:1403] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:38.565543 22883 raft_consensus.cc:359] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00eb7526e88b46c99d181f5609c09baf" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 36215 } }
I20260812 06:18:38.565689 22883 raft_consensus.cc:385] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.565742 22883 raft_consensus.cc:740] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 00eb7526e88b46c99d181f5609c09baf, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.565893 22883 consensus_queue.cc:260] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [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: "00eb7526e88b46c99d181f5609c09baf" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 36215 } }
I20260812 06:18:38.566018 22883 raft_consensus.cc:399] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.566069 22883 raft_consensus.cc:493] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.566128 22883 raft_consensus.cc:3060] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.566956 22883 raft_consensus.cc:515] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00eb7526e88b46c99d181f5609c09baf" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 36215 } }
I20260812 06:18:38.567123 22883 leader_election.cc:304] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [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: 00eb7526e88b46c99d181f5609c09baf; no voters: 
I20260812 06:18:38.567371 22883 leader_election.cc:290] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.567519 22885 raft_consensus.cc:2804] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.567764 22869 heartbeater.cc:499] Master 127.21.250.254:34291 was elected leader, sending a full tablet report...
I20260812 06:18:38.567785 22885 raft_consensus.cc:697] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 1 LEADER]: Becoming Leader. State: Replica: 00eb7526e88b46c99d181f5609c09baf, State: Running, Role: LEADER
I20260812 06:18:38.567754 22883 ts_tablet_manager.cc:1434] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:38.568068 22885 consensus_queue.cc:237] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [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: "00eb7526e88b46c99d181f5609c09baf" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 36215 } }
I20260812 06:18:38.569788 22734 catalog_manager.cc:5719] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf reported cstate change: term changed from 0 to 1, leader changed from <none> to 00eb7526e88b46c99d181f5609c09baf (127.21.250.193). New cstate: current_term: 1 leader_uuid: "00eb7526e88b46c99d181f5609c09baf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00eb7526e88b46c99d181f5609c09baf" member_type: VOTER last_known_addr { host: "127.21.250.193" port: 36215 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:38.631925 22507 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.005s	sys 0.019s
I20260812 06:18:38.781765 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=19.054940
I20260812 06:18:38.944576 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.162s	user 0.098s	sys 0.059s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":126,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":837,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41115,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:38.945290 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50): free 20743831 bytes of WAL
I20260812 06:18:38.945566 22808 log_reader.cc:385] T 6128a0e8c06046f4b3c88ffe5613aa50: removed 2 log segments from log reader
I20260812 06:18:38.945613 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000001 (ops 1-6)
I20260812 06:18:38.945669 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000002 (ops 7-11)
I20260812 06:18:38.949874 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:38.950311 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50): 16411397 bytes on disk
I20260812 06:18:38.950799 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.951277 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:38.969624 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.970194 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:39.132417 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.162s	user 0.097s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":699,"lbm_read_time_us":9848,"lbm_reads_lt_1ms":460,"lbm_write_time_us":28728,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":328,"threads_started":5,"update_count":2000}
I20260812 06:18:39.133221 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:39.183444 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.050s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21830,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.184088 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:39.199751 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.200340 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:39.392156 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.192s	user 0.100s	sys 0.091s 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":926,"lbm_read_time_us":13486,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28801,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:18:39.392928 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:39.449558 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.056s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25497,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.450098 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:39.615659 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.165s	user 0.103s	sys 0.054s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1289,"lbm_read_time_us":11180,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25596,"lbm_writes_lt_1ms":443,"mutex_wait_us":354,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:39.616412 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:39.676137 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.060s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24181,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.676662 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:39.688580 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.689214 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:39.891566 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.202s	user 0.135s	sys 0.058s 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":464,"lbm_read_time_us":11572,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32864,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:39.892280 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:39.944923 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.052s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22571,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.945677 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:39.963352 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.017s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.963861 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:40.123234 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.159s	user 0.138s	sys 0.019s 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":323,"lbm_read_time_us":11872,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31546,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2500}
I20260812 06:18:40.123903 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=10.126437
I20260812 06:18:40.168136 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.044s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18307,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.168680 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.194088 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.025s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.194608 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.206769 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.207556 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:40.238168 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.030s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1755,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1761,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1280}
I20260812 06:18:40.238958 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50): free 112239305 bytes of WAL
I20260812 06:18:40.239252 22808 log_reader.cc:385] T 6128a0e8c06046f4b3c88ffe5613aa50: removed 11 log segments from log reader
I20260812 06:18:40.239326 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000003 (ops 12-16)
I20260812 06:18:40.239385 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000004 (ops 17-20)
I20260812 06:18:40.239440 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000005 (ops 21-25)
I20260812 06:18:40.239483 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000006 (ops 26-30)
I20260812 06:18:40.239514 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000007 (ops 31-35)
I20260812 06:18:40.239559 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000008 (ops 36-40)
I20260812 06:18:40.239596 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000009 (ops 41-45)
I20260812 06:18:40.239634 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000010 (ops 46-50)
I20260812 06:18:40.239670 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000011 (ops 51-55)
I20260812 06:18:40.239708 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000012 (ops 56-60)
I20260812 06:18:40.239753 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000013 (ops 61-65)
I20260812 06:18:40.265816 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:40.266631 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.286780 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.020s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.287251 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.309306 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.022s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.310027 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:40.562753 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.252s	user 0.156s	sys 0.085s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":670,"lbm_read_time_us":19116,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40686,"lbm_writes_lt_1ms":743,"mutex_wait_us":391,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24192,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:40.563850 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=18.063937
I20260812 06:18:40.636638 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.073s	user 0.027s	sys 0.036s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30250,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:40.637245 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50): 447 bytes on disk
I20260812 06:18:40.637765 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.638221 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.650152 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.650709 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:40.867815 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.217s	user 0.141s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":16639,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35099,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":3000}
I20260812 06:18:40.868398 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=15.087375
I20260812 06:18:40.910526 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":18467,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:40.911103 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:40.928339 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.017s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5716,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.928918 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:41.108233 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.179s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":13383,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29000,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.109128 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:41.171672 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.062s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24389,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.172416 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:41.193084 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.020s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.193818 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:41.383109 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.189s	user 0.132s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":11603,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32457,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2500}
I20260812 06:18:41.383932 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:41.454468 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.070s	user 0.030s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26206,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.455121 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:41.474924 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.020s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.475518 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:41.656529 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.181s	user 0.098s	sys 0.078s 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":328,"lbm_read_time_us":11794,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27970,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:41.657094 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:41.716848 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.060s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23720,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.717483 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:41.738976 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.021s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.739643 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:41.774910 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.035s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1467,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:41.775700 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50): free 120553382 bytes of WAL
I20260812 06:18:41.776011 22808 log_reader.cc:385] T 6128a0e8c06046f4b3c88ffe5613aa50: removed 12 log segments from log reader
I20260812 06:18:41.776091 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000014 (ops 66-70)
I20260812 06:18:41.776152 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000015 (ops 71-75)
I20260812 06:18:41.776216 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000016 (ops 76-80)
I20260812 06:18:41.776262 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000017 (ops 81-84)
I20260812 06:18:41.776346 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000018 (ops 85-89)
I20260812 06:18:41.776393 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000019 (ops 90-94)
I20260812 06:18:41.776434 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000020 (ops 95-99)
I20260812 06:18:41.776475 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000021 (ops 100-104)
I20260812 06:18:41.776515 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000022 (ops 105-109)
I20260812 06:18:41.776556 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000023 (ops 110-114)
I20260812 06:18:41.776594 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000024 (ops 115-118)
I20260812 06:18:41.776634 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000025 (ops 119-123)
I20260812 06:18:41.802366 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:41.802891 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:41.826936 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.827436 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50): 447 bytes on disk
I20260812 06:18:41.827863 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50) 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:41.828377 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:41.840628 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.841166 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:42.094887 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.253s	user 0.143s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1370,"lbm_read_time_us":16650,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41290,"lbm_writes_lt_1ms":743,"mutex_wait_us":588,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":132,"threads_started":1,"update_count":3500}
I20260812 06:18:42.095708 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=18.063937
I20260812 06:18:42.157354 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.061s	user 0.034s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29013,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:42.158087 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:42.171541 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.172068 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:42.399001 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.227s	user 0.126s	sys 0.094s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":5689,"dirs.run_cpu_time_us":1835,"dirs.run_wall_time_us":12354,"lbm_read_time_us":14128,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36461,"lbm_writes_lt_1ms":643,"mutex_wait_us":4876,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:42.400314 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=17.071750
I20260812 06:18:42.469261 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.069s	user 0.027s	sys 0.024s Metrics: {"bytes_written":18789300,"delete_count":0,"lbm_write_time_us":24452,"lbm_writes_lt_1ms":461,"reinsert_count":0,"update_count":2290}
I20260812 06:18:42.469856 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=4.173312
I20260812 06:18:42.492430 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.022s	user 0.010s	sys 0.009s Metrics: {"bytes_written":5825684,"delete_count":0,"lbm_write_time_us":9050,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:18:42.493010 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:42.686481 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.193s	user 0.122s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":13758,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31874,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":129,"threads_started":2,"update_count":3000}
I20260812 06:18:42.687347 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=16.079562
I20260812 06:18:42.737803 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":17845750,"delete_count":0,"lbm_write_time_us":20288,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:18:42.738534 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.196750
I20260812 06:18:42.755496 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.017s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3435,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:42.756065 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:42.766728 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.767375 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:42.977859 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.210s	user 0.137s	sys 0.073s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877189,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":471,"lbm_read_time_us":14514,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37802,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":3000}
I20260812 06:18:42.978605 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:43.042210 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.063s	user 0.031s	sys 0.030s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27536,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.042876 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=3.181125
I20260812 06:18:43.059912 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4806,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.060490 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:43.070688 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.071322 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:43.276594 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.205s	user 0.135s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":152,"lbm_read_time_us":13449,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35679,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":3000}
I20260812 06:18:43.278057 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=14.095187
I20260812 06:18:43.327006 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.049s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21287,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.327715 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:43.345752 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.018s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.346328 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:43.379417 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushMRSOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1459,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1828,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:43.380263 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50): free 124257550 bytes of WAL
I20260812 06:18:43.380533 22808 log_reader.cc:385] T 6128a0e8c06046f4b3c88ffe5613aa50: removed 12 log segments from log reader
I20260812 06:18:43.380621 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000026 (ops 124-128)
I20260812 06:18:43.380676 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000027 (ops 129-133)
I20260812 06:18:43.380738 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000028 (ops 134-138)
I20260812 06:18:43.380781 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000029 (ops 139-142)
I20260812 06:18:43.380820 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000030 (ops 143-147)
I20260812 06:18:43.380860 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000031 (ops 148-152)
I20260812 06:18:43.380903 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000032 (ops 153-157)
I20260812 06:18:43.380942 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000033 (ops 158-162)
I20260812 06:18:43.380981 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000034 (ops 163-167)
I20260812 06:18:43.381021 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000035 (ops 168-172)
I20260812 06:18:43.381063 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000036 (ops 173-177)
I20260812 06:18:43.381103 22808 log.cc:1079] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: Deleting log segment in path: /tmp/dist-test-taskOuBrXf/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513012245-22507-0/minicluster-data/ts-0-root/wals/6128a0e8c06046f4b3c88ffe5613aa50/wal-000000037 (ops 178-182)
I20260812 06:18:43.409745 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: LogGCOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:43.410414 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=3.181125
I20260812 06:18:43.426028 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5045,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.426509 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:43.436633 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3747,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.437180 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50): 483 bytes on disk
I20260812 06:18:43.437701 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: UndoDeltaBlockGCOp(6128a0e8c06046f4b3c88ffe5613aa50) 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:43.438666 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:43.676550 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.238s	user 0.149s	sys 0.078s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":618,"lbm_read_time_us":16105,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40496,"lbm_writes_lt_1ms":743,"mutex_wait_us":83,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:18:43.677306 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=18.063937
I20260812 06:18:43.739852 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.062s	user 0.023s	sys 0.037s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28591,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:43.740406 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=2.188937
I20260812 06:18:43.753384 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: FlushDeltaMemStoresOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.754014 22870 maintenance_manager.cc:419] P 00eb7526e88b46c99d181f5609c09baf: Scheduling MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50): perf score=1.000000
I20260812 06:18:43.784806 22507 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.153s	user 1.897s	sys 0.184s
I20260812 06:18:43.844143 22507 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.059s	user 0.001s	sys 0.001s
I20260812 06:18:43.844823 22507 tablet_server.cc:179] TabletServer@127.21.250.193:0 shutting down...
I20260812 06:18:43.913617 22808 maintenance_manager.cc:643] P 00eb7526e88b46c99d181f5609c09baf: MajorDeltaCompactionOp(6128a0e8c06046f4b3c88ffe5613aa50) complete. Timing: real 0.159s	user 0.118s	sys 0.041s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":569,"lbm_read_time_us":12561,"lbm_reads_lt_1ms":668,"lbm_write_time_us":31788,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":162,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":38912,"update_count":3000}
I20260812 06:18:43.914376 22507 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:43.914662 22507 tablet_replica.cc:333] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf: stopping tablet replica
I20260812 06:18:43.914831 22507 raft_consensus.cc:2243] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.915022 22507 raft_consensus.cc:2272] T 6128a0e8c06046f4b3c88ffe5613aa50 P 00eb7526e88b46c99d181f5609c09baf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.920521 22507 tablet_server.cc:196] TabletServer@127.21.250.193:0 shutdown complete.
I20260812 06:18:43.966972 22507 master.cc:562] Master@127.21.250.254:34291 shutting down...
I20260812 06:18:43.970616 22507 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.970868 22507 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.970960 22507 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2363443400a44a3491fcced1ac01ec94: stopping tablet replica
I20260812 06:18:43.983567 22507 master.cc:584] Master@127.21.250.254:34291 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5652 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11052 ms total)

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