[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:03.875301 16072 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.178.62:41867
I20260812 06:20:03.876159 16072 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:20:03.876704 16072 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:03.882449 16080 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:03.882541 16072 server_base.cc:1061] running on GCE node
W20260812 06:20:03.882682 16082 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:03.882782 16079 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:20:03.883195 16072 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:03.883277 16072 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:03.883306 16072 hybrid_clock.cc:648] HybridClock initialized: now 1786515603883304 us; error 0 us; skew 500 ppm
I20260812 06:20:03.884827 16072 webserver.cc:533] Webserver started at http://127.15.178.62:34409/ using document root <none> and password file <none>
I20260812 06:20:03.885308 16072 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:03.885362 16072 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:03.885545 16072 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:03.886979 16072 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/master-0-root/instance:
uuid: "509d01b3be1a4962afa20d675a92dd97"
format_stamp: "Formatted at 2026-08-12 06:20:03 on dist-test-slave-bndk"
I20260812 06:20:03.890010 16072 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:03.891796 16089 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:03.892693 16072 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:03.892791 16072 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/master-0-root
uuid: "509d01b3be1a4962afa20d675a92dd97"
format_stamp: "Formatted at 2026-08-12 06:20:03 on dist-test-slave-bndk"
I20260812 06:20:03.892868 16072 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:03.910557 16072 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:03.911031 16072 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:20:03.911160 16072 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:03.917783 16175 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.178.62:41867 every 8 connection(s)
I20260812 06:20:03.917781 16072 rpc_server.cc:307] RPC server started. Bound to: 127.15.178.62:41867
I20260812 06:20:03.919718 16178 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:03.924600 16178 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: Bootstrap starting.
I20260812 06:20:03.926726 16178 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:03.927531 16178 log.cc:826] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:03.928900 16178 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: No bootstrap required, opened a new log
I20260812 06:20:03.931459 16178 raft_consensus.cc:359] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER }
I20260812 06:20:03.931602 16178 raft_consensus.cc:385] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:03.931672 16178 raft_consensus.cc:740] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 509d01b3be1a4962afa20d675a92dd97, State: Initialized, Role: FOLLOWER
I20260812 06:20:03.932165 16178 consensus_queue.cc:260] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [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: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER }
I20260812 06:20:03.932298 16178 raft_consensus.cc:399] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:03.932358 16178 raft_consensus.cc:493] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:03.932469 16178 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:03.933146 16178 raft_consensus.cc:515] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER }
I20260812 06:20:03.933528 16178 leader_election.cc:304] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [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: 509d01b3be1a4962afa20d675a92dd97; no voters: 
I20260812 06:20:03.933791 16178 leader_election.cc:290] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:03.933880 16182 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:03.934070 16182 raft_consensus.cc:697] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 1 LEADER]: Becoming Leader. State: Replica: 509d01b3be1a4962afa20d675a92dd97, State: Running, Role: LEADER
I20260812 06:20:03.934453 16182 consensus_queue.cc:237] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [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: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER }
I20260812 06:20:03.934607 16178 sys_catalog.cc:565] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:03.936106 16184 sys_catalog.cc:455] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 509d01b3be1a4962afa20d675a92dd97. Latest consensus state: current_term: 1 leader_uuid: "509d01b3be1a4962afa20d675a92dd97" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER } }
I20260812 06:20:03.936133 16183 sys_catalog.cc:455] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "509d01b3be1a4962afa20d675a92dd97" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "509d01b3be1a4962afa20d675a92dd97" member_type: VOTER } }
I20260812 06:20:03.936228 16184 sys_catalog.cc:458] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:03.936228 16183 sys_catalog.cc:458] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:03.936554 16206 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:03.937131 16072 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:03.938539 16206 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:03.942299 16206 catalog_manager.cc:1383] Generated new cluster ID: cfa88fe43ccb4f798966356b069e8e23
I20260812 06:20:03.942355 16206 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:03.973747 16206 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:03.974808 16206 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:03.983825 16206 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: Generated new TSK 0
I20260812 06:20:03.984470 16206 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:04.001760 16072 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:04.004339 16218 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:04.004441 16215 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:20:04.004650 16072 server_base.cc:1061] running on GCE node
W20260812 06:20:04.004637 16220 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:04.004878 16072 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:04.004925 16072 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:04.004953 16072 hybrid_clock.cc:648] HybridClock initialized: now 1786515604004953 us; error 0 us; skew 500 ppm
I20260812 06:20:04.005820 16072 webserver.cc:533] Webserver started at http://127.15.178.1:46113/ using document root <none> and password file <none>
I20260812 06:20:04.005981 16072 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:04.006033 16072 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:04.006103 16072 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:04.006491 16072 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/instance:
uuid: "78058c1d0d9e4392b2676573f178d22a"
format_stamp: "Formatted at 2026-08-12 06:20:04 on dist-test-slave-bndk"
I20260812 06:20:04.008163 16072 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:04.009158 16231 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:04.009404 16072 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:04.009469 16072 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root
uuid: "78058c1d0d9e4392b2676573f178d22a"
format_stamp: "Formatted at 2026-08-12 06:20:04 on dist-test-slave-bndk"
I20260812 06:20:04.009541 16072 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:04.023528 16072 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:04.023859 16072 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:04.024237 16072 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:04.024967 16072 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:04.025018 16072 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:04.025069 16072 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:04.025094 16072 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:04.031049 16072 rpc_server.cc:307] RPC server started. Bound to: 127.15.178.1:46375
I20260812 06:20:04.031195 16343 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.178.1:46375 every 8 connection(s)
I20260812 06:20:04.042778 16345 heartbeater.cc:344] Connected to a master server at 127.15.178.62:41867
I20260812 06:20:04.042973 16345 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:04.043346 16345 heartbeater.cc:507] Master 127.15.178.62:41867 requested a full tablet report, sending...
I20260812 06:20:04.044564 16117 ts_manager.cc:194] Registered new tserver with Master: 78058c1d0d9e4392b2676573f178d22a (127.15.178.1:46375)
I20260812 06:20:04.044871 16072 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013229635s
I20260812 06:20:04.045892 16117 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39158
I20260812 06:20:04.052985 16117 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39168:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:04.065966 16277 tablet_service.cc:1511] Processing CreateTablet for tablet 45b3122677564351b31340af24ed8ac5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2efdba574a834ad29efc93bf034bd7ce]), partition=
I20260812 06:20:04.066335 16277 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 45b3122677564351b31340af24ed8ac5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:04.068521 16366 tablet_bootstrap.cc:492] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Bootstrap starting.
I20260812 06:20:04.069399 16366 tablet_bootstrap.cc:654] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:04.070735 16366 tablet_bootstrap.cc:492] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: No bootstrap required, opened a new log
I20260812 06:20:04.070825 16366 ts_tablet_manager.cc:1403] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:04.071223 16366 raft_consensus.cc:359] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "78058c1d0d9e4392b2676573f178d22a" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 46375 } }
I20260812 06:20:04.071324 16366 raft_consensus.cc:385] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:04.071357 16366 raft_consensus.cc:740] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 78058c1d0d9e4392b2676573f178d22a, State: Initialized, Role: FOLLOWER
I20260812 06:20:04.071480 16366 consensus_queue.cc:260] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [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: "78058c1d0d9e4392b2676573f178d22a" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 46375 } }
I20260812 06:20:04.071576 16366 raft_consensus.cc:399] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:04.071620 16366 raft_consensus.cc:493] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:04.071667 16366 raft_consensus.cc:3060] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:04.072336 16366 raft_consensus.cc:515] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "78058c1d0d9e4392b2676573f178d22a" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 46375 } }
I20260812 06:20:04.072455 16366 leader_election.cc:304] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [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: 78058c1d0d9e4392b2676573f178d22a; no voters: 
I20260812 06:20:04.072636 16366 leader_election.cc:290] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:04.072739 16370 raft_consensus.cc:2804] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:04.072942 16366 ts_tablet_manager.cc:1434] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:04.072978 16370 raft_consensus.cc:697] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 1 LEADER]: Becoming Leader. State: Replica: 78058c1d0d9e4392b2676573f178d22a, State: Running, Role: LEADER
I20260812 06:20:04.073146 16345 heartbeater.cc:499] Master 127.15.178.62:41867 was elected leader, sending a full tablet report...
I20260812 06:20:04.073154 16370 consensus_queue.cc:237] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [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: "78058c1d0d9e4392b2676573f178d22a" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 46375 } }
I20260812 06:20:04.075847 16117 catalog_manager.cc:5719] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a reported cstate change: term changed from 0 to 1, leader changed from <none> to 78058c1d0d9e4392b2676573f178d22a (127.15.178.1). New cstate: current_term: 1 leader_uuid: "78058c1d0d9e4392b2676573f178d22a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "78058c1d0d9e4392b2676573f178d22a" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 46375 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:04.131914 16072 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.018s	sys 0.005s
I20260812 06:20:04.282094 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushMRSOp(45b3122677564351b31340af24ed8ac5): perf score=23.023690
I20260812 06:20:04.482452 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushMRSOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.200s	user 0.159s	sys 0.037s Metrics: {"bytes_written":16409902,"cfile_init":1,"compiler_manager_pool.queue_time_us":183,"delete_count":0,"dirs.queue_time_us":29,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":863,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":51970,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":101,"threads_started":1,"update_count":2000}
I20260812 06:20:04.483727 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 20743880 bytes of WAL
I20260812 06:20:04.484018 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 2 log segments from log reader
I20260812 06:20:04.484095 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000001 (ops 1-6)
I20260812 06:20:04.484205 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000002 (ops 7-11)
I20260812 06:20:04.489477 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:04.489796 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=3.181125
I20260812 06:20:04.504374 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.014s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5281,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.504745 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:04.516124 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.516544 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:04.698096 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.181s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":533,"lbm_read_time_us":10446,"lbm_reads_lt_1ms":673,"lbm_write_time_us":28525,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":257,"threads_started":5,"update_count":3000}
I20260812 06:20:04.698627 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5): 20513814 bytes on disk
I20260812 06:20:04.699115 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.699522 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:04.754189 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.055s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17755,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:04.754577 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:04.764042 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.764422 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:04.923827 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.159s	user 0.101s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":11369,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25575,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:04.924360 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:04.972208 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.048s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20993,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.972659 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:04.987376 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.987872 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:05.151813 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.164s	user 0.108s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":10821,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26732,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:20:05.152266 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:05.212857 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.060s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24115,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.213367 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.223317 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.223767 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:05.384210 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.160s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":11436,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26979,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:20:05.384912 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=11.118625
I20260812 06:20:05.419443 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.034s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":14139,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.419996 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.450242 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.030s	user 0.004s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.450688 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.460374 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.460733 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:05.621021 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.160s	user 0.095s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1540,"lbm_read_time_us":11279,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26595,"lbm_writes_lt_1ms":543,"mutex_wait_us":683,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:05.621523 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:05.650835 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.029s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12544,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.651422 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.666687 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.667126 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushMRSOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:05.693924 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushMRSOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":34,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1321,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1659,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:05.694895 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 121006422 bytes of WAL
I20260812 06:20:05.695106 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 12 log segments from log reader
I20260812 06:20:05.695158 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000003 (ops 12-16)
I20260812 06:20:05.695194 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000004 (ops 17-21)
I20260812 06:20:05.695225 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000005 (ops 22-26)
I20260812 06:20:05.695252 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000006 (ops 27-31)
I20260812 06:20:05.695277 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000007 (ops 32-36)
I20260812 06:20:05.695299 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000008 (ops 37-41)
I20260812 06:20:05.695333 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000009 (ops 42-46)
I20260812 06:20:05.695355 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000010 (ops 47-51)
I20260812 06:20:05.695375 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000011 (ops 52-56)
I20260812 06:20:05.695396 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000012 (ops 57-60)
I20260812 06:20:05.695416 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000013 (ops 61-65)
I20260812 06:20:05.695436 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000014 (ops 66-70)
I20260812 06:20:05.720666 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:05.721069 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5): 472 bytes on disk
I20260812 06:20:05.721493 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.721932 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=3.181125
I20260812 06:20:05.736960 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.015s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:05.737397 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.750581 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.751030 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:05.925159 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.174s	user 0.097s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":516,"lbm_read_time_us":12633,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29993,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:20:05.925639 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:05.980635 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.055s	user 0.037s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20670,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.981112 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:05.990867 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.991263 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.141791 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.150s	user 0.085s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":11237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24197,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:06.142336 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=11.118625
I20260812 06:20:06.175420 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13433,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.175917 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:06.189350 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.013s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.189823 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.322248 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.132s	user 0.087s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":6925,"lbm_reads_lt_1ms":468,"lbm_write_time_us":21026,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:20:06.322742 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:06.355867 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14248,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.356604 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:06.371520 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.371989 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.488570 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.116s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":6836,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22655,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:06.491847 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:06.521265 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.029s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12444,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.521695 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:06.532457 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.532998 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.641927 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.109s	user 0.093s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":7235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19740,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:20:06.642359 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:06.683439 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.041s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13585,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.683882 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:06.693725 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.694150 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.837332 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.143s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1353,"lbm_read_time_us":9954,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21440,"lbm_writes_lt_1ms":443,"mutex_wait_us":802,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:06.837816 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:06.869990 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.032s	user 0.023s	sys 0.005s Metrics: {"bytes_written":12307496,"delete_count":0,"lbm_write_time_us":12271,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.870673 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:06.975870 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.105s	user 0.069s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":152,"lbm_read_time_us":5955,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19533,"lbm_writes_lt_1ms":343,"mutex_wait_us":23,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:20:06.976420 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=10.126437
I20260812 06:20:07.019904 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.043s	user 0.003s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.020336 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.029683 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.030387 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushMRSOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:07.056944 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushMRSOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":28,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1265,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:07.057642 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 124257245 bytes of WAL
I20260812 06:20:07.057843 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 12 log segments from log reader
I20260812 06:20:07.057886 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000015 (ops 71-75)
I20260812 06:20:07.057914 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000016 (ops 76-80)
I20260812 06:20:07.057945 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000017 (ops 81-85)
I20260812 06:20:07.057977 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000018 (ops 86-90)
I20260812 06:20:07.058015 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000019 (ops 91-95)
I20260812 06:20:07.058048 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000020 (ops 96-100)
I20260812 06:20:07.058080 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000021 (ops 101-105)
I20260812 06:20:07.058111 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000022 (ops 106-110)
I20260812 06:20:07.058142 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000023 (ops 111-115)
I20260812 06:20:07.058174 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000024 (ops 116-120)
I20260812 06:20:07.058204 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000025 (ops 121-124)
I20260812 06:20:07.058235 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000026 (ops 125-129)
I20260812 06:20:07.080209 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:07.080605 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5): 473 bytes on disk
I20260812 06:20:07.081010 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.081532 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=3.181125
I20260812 06:20:07.095248 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:07.095605 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 12017954 bytes of WAL
I20260812 06:20:07.095778 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 1 log segments from log reader
I20260812 06:20:07.095831 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000027 (ops 130-134)
I20260812 06:20:07.098261 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:07.098506 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.112301 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5264,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.112679 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:07.271672 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.159s	user 0.130s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":626,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30973,"lbm_writes_lt_1ms":643,"mutex_wait_us":246,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:20:07.272177 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:07.316828 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.045s	user 0.038s	sys 0.000s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.317341 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.331707 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.332170 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:07.477497 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.145s	user 0.117s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":105,"lbm_read_time_us":9271,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26569,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:07.478832 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=13.103000
I20260812 06:20:07.524745 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.046s	user 0.016s	sys 0.024s Metrics: {"bytes_written":14604842,"delete_count":0,"lbm_write_time_us":16177,"lbm_writes_lt_1ms":359,"reinsert_count":0,"update_count":1780}
I20260812 06:20:07.525288 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=1.196750
I20260812 06:20:07.535545 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2215508,"delete_count":0,"lbm_write_time_us":2127,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:20:07.536058 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.544468 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3121,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.544836 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:07.693388 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.148s	user 0.093s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":470,"lbm_read_time_us":10435,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25352,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:20:07.694293 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=11.118625
I20260812 06:20:07.739066 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.044s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12840809,"delete_count":0,"lbm_write_time_us":15115,"lbm_writes_lt_1ms":316,"reinsert_count":0,"update_count":1565}
I20260812 06:20:07.739555 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.758723 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":5143,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:20:07.759238 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:07.769834 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.770278 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:07.951884 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.181s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815792,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3538,"lbm_read_time_us":13172,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27205,"lbm_writes_lt_1ms":543,"mutex_wait_us":2903,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:20:07.952409 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:08.005836 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.053s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20325,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.006376 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:08.017866 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.018332 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:08.178344 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.160s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":10695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24596,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:08.178870 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:08.241403 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.062s	user 0.040s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21535,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.241969 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:08.252170 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.252688 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:08.429425 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.177s	user 0.121s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4067,"lbm_read_time_us":11067,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27906,"lbm_writes_lt_1ms":543,"mutex_wait_us":3807,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:20:08.429947 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=14.095187
I20260812 06:20:08.476600 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.046s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.477118 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:08.493566 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.016s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.494118 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushMRSOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:08.523878 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushMRSOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":168,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:08.524494 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 121459769 bytes of WAL
I20260812 06:20:08.524704 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 12 log segments from log reader
I20260812 06:20:08.524750 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000028 (ops 135-139)
I20260812 06:20:08.524778 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000029 (ops 140-144)
I20260812 06:20:08.524809 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000030 (ops 145-149)
I20260812 06:20:08.524840 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000031 (ops 150-154)
I20260812 06:20:08.524873 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000032 (ops 155-159)
I20260812 06:20:08.524904 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000033 (ops 160-164)
I20260812 06:20:08.524935 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000034 (ops 165-169)
I20260812 06:20:08.524966 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000035 (ops 170-174)
I20260812 06:20:08.525007 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000036 (ops 175-179)
I20260812 06:20:08.525038 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000037 (ops 180-184)
I20260812 06:20:08.525068 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000038 (ops 185-189)
I20260812 06:20:08.525099 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000039 (ops 190-194)
I20260812 06:20:08.546432 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:08.546849 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=3.181125
I20260812 06:20:08.568110 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.021s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6756,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:08.568529 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling LogGCOp(45b3122677564351b31340af24ed8ac5): free 11564893 bytes of WAL
I20260812 06:20:08.568712 16242 log_reader.cc:385] T 45b3122677564351b31340af24ed8ac5: removed 1 log segments from log reader
I20260812 06:20:08.568756 16242 log.cc:1079] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/45b3122677564351b31340af24ed8ac5/wal-000000040 (ops 195-198)
I20260812 06:20:08.570569 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: LogGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:08.570870 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5): 492 bytes on disk
I20260812 06:20:08.571242 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: UndoDeltaBlockGCOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:20:08.571748 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5): perf score=2.188937
I20260812 06:20:08.580776 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: FlushDeltaMemStoresOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3308,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.581144 16348 maintenance_manager.cc:419] P 78058c1d0d9e4392b2676573f178d22a: Scheduling MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5): perf score=1.000000
I20260812 06:20:08.608656 16072 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.477s	user 1.633s	sys 0.135s
I20260812 06:20:08.735384 16072 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.126s	user 0.001s	sys 0.000s
I20260812 06:20:08.736040 16072 tablet_server.cc:179] TabletServer@127.15.178.1:0 shutting down...
I20260812 06:20:08.794277 16242 maintenance_manager.cc:643] P 78058c1d0d9e4392b2676573f178d22a: MajorDeltaCompactionOp(45b3122677564351b31340af24ed8ac5) complete. Timing: real 0.213s	user 0.130s	sys 0.081s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":319,"lbm_read_time_us":13557,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37638,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":53376,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:20:08.795249 16072 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:08.795629 16072 tablet_replica.cc:333] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a: stopping tablet replica
I20260812 06:20:08.795854 16072 raft_consensus.cc:2243] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.796087 16072 raft_consensus.cc:2272] T 45b3122677564351b31340af24ed8ac5 P 78058c1d0d9e4392b2676573f178d22a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.809278 16072 tablet_server.cc:196] TabletServer@127.15.178.1:0 shutdown complete.
I20260812 06:20:08.850579 16072 master.cc:562] Master@127.15.178.62:41867 shutting down...
I20260812 06:20:08.853826 16072 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.853991 16072 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.854065 16072 tablet_replica.cc:333] T 00000000000000000000000000000000 P 509d01b3be1a4962afa20d675a92dd97: stopping tablet replica
I20260812 06:20:08.866139 16072 master.cc:584] Master@127.15.178.62:41867 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5064 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:08.940356 16072 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.178.62:41241
I20260812 06:20:08.941062 16072 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:08.944070 16404 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:08.943975 16401 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:08.944077 16072 server_base.cc:1061] running on GCE node
W20260812 06:20:08.943979 16396 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:20:08.944597 16072 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:08.944651 16072 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:08.944675 16072 hybrid_clock.cc:648] HybridClock initialized: now 1786515608944675 us; error 0 us; skew 500 ppm
I20260812 06:20:08.945798 16072 webserver.cc:533] Webserver started at http://127.15.178.62:42023/ using document root <none> and password file <none>
I20260812 06:20:08.946044 16072 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:08.946134 16072 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:08.946261 16072 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:08.946873 16072 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/master-0-root/instance:
uuid: "f124cb4fe05b434abe5ae6daf7f69663"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-bndk"
I20260812 06:20:08.949071 16072 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:20:08.950419 16413 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:08.950722 16072 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:08.950816 16072 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/master-0-root
uuid: "f124cb4fe05b434abe5ae6daf7f69663"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-bndk"
I20260812 06:20:08.950915 16072 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:08.971161 16072 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:08.971536 16072 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:08.978204 16072 rpc_server.cc:307] RPC server started. Bound to: 127.15.178.62:41241
I20260812 06:20:08.990494 16519 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.178.62:41241 every 8 connection(s)
I20260812 06:20:08.991132 16520 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:08.994118 16520 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663: Bootstrap starting.
I20260812 06:20:08.995385 16520 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:08.996842 16520 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663: No bootstrap required, opened a new log
I20260812 06:20:08.997452 16520 raft_consensus.cc:359] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER }
I20260812 06:20:08.997593 16520 raft_consensus.cc:385] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:08.997656 16520 raft_consensus.cc:740] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f124cb4fe05b434abe5ae6daf7f69663, State: Initialized, Role: FOLLOWER
I20260812 06:20:08.997814 16520 consensus_queue.cc:260] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [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: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER }
I20260812 06:20:08.997907 16520 raft_consensus.cc:399] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:08.997953 16520 raft_consensus.cc:493] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:08.998006 16520 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:08.998952 16520 raft_consensus.cc:515] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER }
I20260812 06:20:08.999141 16520 leader_election.cc:304] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [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: f124cb4fe05b434abe5ae6daf7f69663; no voters: 
I20260812 06:20:08.999372 16520 leader_election.cc:290] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:08.999542 16530 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:08.999837 16530 raft_consensus.cc:697] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 1 LEADER]: Becoming Leader. State: Replica: f124cb4fe05b434abe5ae6daf7f69663, State: Running, Role: LEADER
I20260812 06:20:09.000051 16530 consensus_queue.cc:237] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [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: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER }
I20260812 06:20:09.000075 16520 sys_catalog.cc:565] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:09.000706 16534 sys_catalog.cc:455] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f124cb4fe05b434abe5ae6daf7f69663. Latest consensus state: current_term: 1 leader_uuid: "f124cb4fe05b434abe5ae6daf7f69663" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER } }
I20260812 06:20:09.000861 16534 sys_catalog.cc:458] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:09.001243 16531 sys_catalog.cc:455] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f124cb4fe05b434abe5ae6daf7f69663" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f124cb4fe05b434abe5ae6daf7f69663" member_type: VOTER } }
I20260812 06:20:09.001389 16531 sys_catalog.cc:458] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:09.001812 16536 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:09.003417 16536 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:09.003690 16072 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:09.006198 16536 catalog_manager.cc:1383] Generated new cluster ID: 94b0bb05cc4f4ff1b4175897b3a0ad90
I20260812 06:20:09.006279 16536 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:09.049836 16536 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:09.050503 16536 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:09.057572 16536 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663: Generated new TSK 0
I20260812 06:20:09.057760 16536 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:09.068502 16072 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:09.070663 16570 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:09.070725 16565 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:09.070833 16567 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:09.071053 16072 server_base.cc:1061] running on GCE node
I20260812 06:20:09.071241 16072 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:09.071301 16072 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:20:09.071324 16072 hybrid_clock.cc:648] HybridClock initialized: now 1786515609071325 us; error 0 us; skew 500 ppm
I20260812 06:20:09.072167 16072 webserver.cc:533] Webserver started at http://127.15.178.1:33455/ using document root <none> and password file <none>
I20260812 06:20:09.072340 16072 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:09.072420 16072 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:09.072516 16072 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:09.072984 16072 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/instance:
uuid: "f06a3e1ac2554628aa4d7d09eed358e1"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bndk"
I20260812 06:20:09.074997 16072 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:09.076176 16587 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:09.076442 16072 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:09.076537 16072 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root
uuid: "f06a3e1ac2554628aa4d7d09eed358e1"
format_stamp: "Formatted at 2026-08-12 06:20:09 on dist-test-slave-bndk"
I20260812 06:20:09.076629 16072 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:20:09.088832 16072 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:09.089357 16072 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:09.089704 16072 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:09.090286 16072 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:09.090344 16072 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:09.090425 16072 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:09.090471 16072 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:09.096801 16072 rpc_server.cc:307] RPC server started. Bound to: 127.15.178.1:35745
I20260812 06:20:09.096874 16729 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.178.1:35745 every 8 connection(s)
I20260812 06:20:09.111169 16732 heartbeater.cc:344] Connected to a master server at 127.15.178.62:41241
I20260812 06:20:09.111321 16732 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:09.111637 16732 heartbeater.cc:507] Master 127.15.178.62:41241 requested a full tablet report, sending...
I20260812 06:20:09.112473 16442 ts_manager.cc:194] Registered new tserver with Master: f06a3e1ac2554628aa4d7d09eed358e1 (127.15.178.1:35745)
I20260812 06:20:09.112823 16072 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015406873s
I20260812 06:20:09.113840 16442 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54414
I20260812 06:20:09.121734 16442 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54424:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:09.132030 16656 tablet_service.cc:1511] Processing CreateTablet for tablet 762e03d69bea4acc8472962028120476 (DEFAULT_TABLE table=heavy-update-compaction-test [id=fe1289f8163c4d52932af5b7b3e80b6f]), partition=
I20260812 06:20:09.132345 16656 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 762e03d69bea4acc8472962028120476. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:09.134754 16750 tablet_bootstrap.cc:492] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Bootstrap starting.
I20260812 06:20:09.135825 16750 tablet_bootstrap.cc:654] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:09.137274 16750 tablet_bootstrap.cc:492] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: No bootstrap required, opened a new log
I20260812 06:20:09.137384 16750 ts_tablet_manager.cc:1403] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:09.137928 16750 raft_consensus.cc:359] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f06a3e1ac2554628aa4d7d09eed358e1" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 35745 } }
I20260812 06:20:09.138046 16750 raft_consensus.cc:385] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:09.138111 16750 raft_consensus.cc:740] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f06a3e1ac2554628aa4d7d09eed358e1, State: Initialized, Role: FOLLOWER
I20260812 06:20:09.138293 16750 consensus_queue.cc:260] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [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: "f06a3e1ac2554628aa4d7d09eed358e1" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 35745 } }
I20260812 06:20:09.138403 16750 raft_consensus.cc:399] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:09.138465 16750 raft_consensus.cc:493] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:09.138540 16750 raft_consensus.cc:3060] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:09.139446 16750 raft_consensus.cc:515] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f06a3e1ac2554628aa4d7d09eed358e1" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 35745 } }
I20260812 06:20:09.139611 16750 leader_election.cc:304] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [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: f06a3e1ac2554628aa4d7d09eed358e1; no voters: 
I20260812 06:20:09.139850 16750 leader_election.cc:290] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:09.139988 16753 raft_consensus.cc:2804] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:09.140242 16753 raft_consensus.cc:697] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 1 LEADER]: Becoming Leader. State: Replica: f06a3e1ac2554628aa4d7d09eed358e1, State: Running, Role: LEADER
I20260812 06:20:09.140292 16750 ts_tablet_manager.cc:1434] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:09.140522 16732 heartbeater.cc:499] Master 127.15.178.62:41241 was elected leader, sending a full tablet report...
I20260812 06:20:09.140470 16753 consensus_queue.cc:237] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [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: "f06a3e1ac2554628aa4d7d09eed358e1" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 35745 } }
I20260812 06:20:09.142184 16442 catalog_manager.cc:5719] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 reported cstate change: term changed from 0 to 1, leader changed from <none> to f06a3e1ac2554628aa4d7d09eed358e1 (127.15.178.1). New cstate: current_term: 1 leader_uuid: "f06a3e1ac2554628aa4d7d09eed358e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f06a3e1ac2554628aa4d7d09eed358e1" member_type: VOTER last_known_addr { host: "127.15.178.1" port: 35745 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:09.221318 16072 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.074s	user 0.021s	sys 0.010s
I20260812 06:20:09.348172 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushMRSOp(762e03d69bea4acc8472962028120476): perf score=10.125253
I20260812 06:20:09.540023 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushMRSOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.191s	user 0.126s	sys 0.055s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":947,"drs_written":1,"lbm_read_time_us":150,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44113,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"update_count":1000}
I20260812 06:20:09.541090 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling LogGCOp(762e03d69bea4acc8472962028120476): free 8725963 bytes of WAL
I20260812 06:20:09.541471 16597 log_reader.cc:385] T 762e03d69bea4acc8472962028120476: removed 1 log segments from log reader
I20260812 06:20:09.541560 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000001 (ops 1-6)
I20260812 06:20:09.544878 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: LogGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:09.545395 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476): 8206537 bytes on disk
I20260812 06:20:09.545969 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.546495 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:09.563385 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.563944 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:09.712081 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.148s	user 0.083s	sys 0.064s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":500,"lbm_read_time_us":15437,"lbm_reads_lt_1ms":364,"lbm_write_time_us":17533,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":292,"threads_started":5,"update_count":1500}
I20260812 06:20:09.712590 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=7.149875
I20260812 06:20:09.734887 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.022s	user 0.012s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9129,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:09.735296 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:09.748435 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4904,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.748893 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:09.853749 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.105s	user 0.081s	sys 0.019s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":7719,"lbm_reads_lt_1ms":372,"lbm_write_time_us":16757,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":1500}
I20260812 06:20:09.854171 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=7.149875
I20260812 06:20:09.883713 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.029s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11513,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:09.884171 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:09.892995 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3319,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.893440 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.011492 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.118s	user 0.075s	sys 0.041s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487926,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":425,"lbm_read_time_us":8574,"lbm_reads_lt_1ms":372,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":343,"mutex_wait_us":274,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:20:10.011987 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:10.055155 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.043s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:20:10.055660 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.070367 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.015s	user 0.000s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.070822 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.183960 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.113s	user 0.082s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":696,"lbm_read_time_us":8034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20101,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:20:10.184453 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:10.225759 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.041s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11977,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.226166 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.235982 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.236599 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.355086 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.118s	user 0.088s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":9079,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21970,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:20:10.355618 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:10.396412 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.041s	user 0.015s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.396937 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.407487 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.407982 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.524199 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.116s	user 0.100s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":373,"lbm_read_time_us":7873,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21301,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:10.524740 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:10.566994 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.042s	user 0.026s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13921,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.567481 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.582175 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.582617 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.718940 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.136s	user 0.086s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":135,"lbm_read_time_us":11322,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19947,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.719717 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:10.751974 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.032s	user 0.016s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12440,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:10.752496 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.767174 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.767649 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushMRSOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:10.794559 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushMRSOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":33,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1309,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1391,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:10.795188 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling LogGCOp(762e03d69bea4acc8472962028120476): free 123804187 bytes of WAL
I20260812 06:20:10.795390 16597 log_reader.cc:385] T 762e03d69bea4acc8472962028120476: removed 12 log segments from log reader
I20260812 06:20:10.795437 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000002 (ops 7-10)
I20260812 06:20:10.795480 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000003 (ops 11-15)
I20260812 06:20:10.795508 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000004 (ops 16-20)
I20260812 06:20:10.795533 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000005 (ops 21-24)
I20260812 06:20:10.795564 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000006 (ops 25-29)
I20260812 06:20:10.795594 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000007 (ops 30-34)
I20260812 06:20:10.795621 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000008 (ops 35-39)
I20260812 06:20:10.795647 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000009 (ops 40-44)
I20260812 06:20:10.795682 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000010 (ops 45-49)
I20260812 06:20:10.795714 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000011 (ops 50-54)
I20260812 06:20:10.795743 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000012 (ops 55-59)
I20260812 06:20:10.795770 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000013 (ops 60-64)
I20260812 06:20:10.821772 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: LogGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:10.822145 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=3.181125
I20260812 06:20:10.847958 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.026s	user 0.014s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6420,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:10.848347 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:10.857131 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3331,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:10.857501 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:11.039987 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.182s	user 0.119s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795396,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":399,"lbm_read_time_us":12706,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28363,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:20:11.040518 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:11.095683 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.054s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18301,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.096154 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:11.106132 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.106509 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476): 462 bytes on disk
I20260812 06:20:11.106864 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:20:11.107265 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:11.280061 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.173s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":712,"lbm_read_time_us":11577,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28494,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:11.280555 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=11.118625
I20260812 06:20:11.318022 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.037s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15534,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:11.318614 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:11.342375 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.024s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.342836 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:11.365482 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.022s	user 0.011s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.366037 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:11.544988 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.179s	user 0.106s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":126,"lbm_read_time_us":10884,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25769,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.545512 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:11.593662 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.048s	user 0.037s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.594161 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:11.609051 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.609714 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:11.776688 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.167s	user 0.102s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":11000,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25361,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:20:11.777282 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:11.826526 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.049s	user 0.019s	sys 0.025s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.826932 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:11.836678 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.837291 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:11.972097 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.135s	user 0.099s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692756,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":455,"lbm_read_time_us":9113,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25177,"lbm_writes_lt_1ms":543,"mutex_wait_us":260,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:20:11.972724 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=11.118625
I20260812 06:20:12.000523 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.028s	user 0.020s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11391,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:12.001362 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:12.027166 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.026s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4939,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.027664 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:12.038631 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.039037 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:12.168111 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.129s	user 0.115s	sys 0.013s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692868,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":512,"lbm_read_time_us":10135,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24065,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:20:12.168654 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=11.118625
I20260812 06:20:12.196836 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":11578,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:12.197378 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:12.220607 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.221079 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:12.235348 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.235791 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushMRSOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:12.264415 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushMRSOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.028s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1210,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1459,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:12.265182 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling LogGCOp(762e03d69bea4acc8472962028120476): free 129773557 bytes of WAL
I20260812 06:20:12.265440 16597 log_reader.cc:385] T 762e03d69bea4acc8472962028120476: removed 13 log segments from log reader
I20260812 06:20:12.265491 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000014 (ops 65-69)
I20260812 06:20:12.265529 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000015 (ops 70-74)
I20260812 06:20:12.265563 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000016 (ops 75-79)
I20260812 06:20:12.265594 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000017 (ops 80-84)
I20260812 06:20:12.265625 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000018 (ops 85-89)
I20260812 06:20:12.265655 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000019 (ops 90-94)
I20260812 06:20:12.265687 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000020 (ops 95-99)
I20260812 06:20:12.265717 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000021 (ops 100-104)
I20260812 06:20:12.265748 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000022 (ops 105-108)
I20260812 06:20:12.265780 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000023 (ops 109-113)
I20260812 06:20:12.265810 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000024 (ops 114-118)
I20260812 06:20:12.265841 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000025 (ops 119-123)
I20260812 06:20:12.265872 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000026 (ops 124-128)
I20260812 06:20:12.288857 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: LogGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:20:12.289325 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=3.181125
I20260812 06:20:12.307550 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.018s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6835,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:12.307993 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:12.317150 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3632,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.317623 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476): 492 bytes on disk
I20260812 06:20:12.318005 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.318466 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:12.539830 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.221s	user 0.138s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32897916,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":215,"lbm_read_time_us":13877,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36673,"lbm_writes_lt_1ms":743,"mutex_wait_us":1,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":71,"threads_started":1,"update_count":3500}
I20260812 06:20:12.540414 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=15.087375
I20260812 06:20:12.610198 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.070s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":25978,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:20:12.610666 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=6.157687
I20260812 06:20:12.635156 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.024s	user 0.009s	sys 0.013s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10378,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:12.635560 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:12.833735 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.198s	user 0.131s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795170,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":8290,"dirs.run_cpu_time_us":889,"dirs.run_wall_time_us":8600,"lbm_read_time_us":13841,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29621,"lbm_writes_lt_1ms":643,"mutex_wait_us":3928,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3000}
I20260812 06:20:12.834360 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=17.071750
I20260812 06:20:12.895933 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.061s	user 0.042s	sys 0.008s Metrics: {"bytes_written":19076467,"delete_count":0,"lbm_write_time_us":23498,"lbm_writes_lt_1ms":468,"reinsert_count":0,"update_count":2325}
I20260812 06:20:12.896449 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=4.173312
I20260812 06:20:12.916268 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.020s	user 0.011s	sys 0.007s Metrics: {"bytes_written":5538513,"delete_count":0,"lbm_write_time_us":7878,"lbm_writes_lt_1ms":138,"reinsert_count":0,"update_count":675}
I20260812 06:20:12.916709 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.109158 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.192s	user 0.144s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795172,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":13644,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35451,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:20:13.110035 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:13.148610 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.038s	user 0.019s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16734,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.149057 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:13.159380 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.159765 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.325397 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.165s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":12728,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26104,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:20:13.325986 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:13.371376 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.045s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":15542,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.371951 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:13.382300 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.382781 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.533360 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.150s	user 0.121s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":11524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24571,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:13.534061 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:13.562583 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.563112 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:13.584383 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.585793 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushMRSOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.610685 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushMRSOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.025s	user 0.022s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1131,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1402,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:13.611438 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling LogGCOp(762e03d69bea4acc8472962028120476): free 111786446 bytes of WAL
I20260812 06:20:13.611654 16597 log_reader.cc:385] T 762e03d69bea4acc8472962028120476: removed 11 log segments from log reader
I20260812 06:20:13.611702 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000027 (ops 129-132)
I20260812 06:20:13.611742 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000028 (ops 133-137)
I20260812 06:20:13.611773 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000029 (ops 138-142)
I20260812 06:20:13.611799 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000030 (ops 143-147)
I20260812 06:20:13.611829 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000031 (ops 148-152)
I20260812 06:20:13.611860 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000032 (ops 153-157)
I20260812 06:20:13.611891 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000033 (ops 158-162)
I20260812 06:20:13.611922 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000034 (ops 163-167)
I20260812 06:20:13.611948 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000035 (ops 168-172)
I20260812 06:20:13.611972 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000036 (ops 173-176)
I20260812 06:20:13.612002 16597 log.cc:1079] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: Deleting log segment in path: /tmp/dist-test-task5yC3fU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515603865423-16072-0/minicluster-data/ts-0-root/wals/762e03d69bea4acc8472962028120476/wal-000000037 (ops 177-181)
I20260812 06:20:13.631803 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: LogGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.020s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:20:13.632215 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476): 446 bytes on disk
I20260812 06:20:13.632715 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: UndoDeltaBlockGCOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.633338 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:13.650380 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.650779 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=2.188937
I20260812 06:20:13.660130 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.660512 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.842912 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.182s	user 0.123s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795407,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":263,"lbm_read_time_us":12913,"lbm_reads_lt_1ms":674,"lbm_write_time_us":27528,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:13.843401 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=14.095187
I20260812 06:20:13.886592 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.043s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17875,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.887174 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476): perf score=1.000000
I20260812 06:20:13.980705 16072 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.759s	user 1.759s	sys 0.157s
I20260812 06:20:14.011762 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: MajorDeltaCompactionOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.124s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590227,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":9827,"lbm_reads_lt_1ms":459,"lbm_write_time_us":19083,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:20:14.012306 16737 maintenance_manager.cc:419] P f06a3e1ac2554628aa4d7d09eed358e1: Scheduling FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476): perf score=10.126437
I20260812 06:20:14.027431 16072 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.046s	user 0.001s	sys 0.000s
I20260812 06:20:14.027858 16072 tablet_server.cc:179] TabletServer@127.15.178.1:0 shutting down...
I20260812 06:20:14.041121 16597 maintenance_manager.cc:643] P f06a3e1ac2554628aa4d7d09eed358e1: FlushDeltaMemStoresOp(762e03d69bea4acc8472962028120476) complete. Timing: real 0.029s	user 0.026s	sys 0.000s Metrics: {"bytes_written":12307558,"delete_count":0,"lbm_write_time_us":12028,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.041605 16072 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:14.041796 16072 tablet_replica.cc:333] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1: stopping tablet replica
I20260812 06:20:14.041920 16072 raft_consensus.cc:2243] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:14.042080 16072 raft_consensus.cc:2272] T 762e03d69bea4acc8472962028120476 P f06a3e1ac2554628aa4d7d09eed358e1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:14.056226 16072 tablet_server.cc:196] TabletServer@127.15.178.1:0 shutdown complete.
I20260812 06:20:14.058738 16072 master.cc:562] Master@127.15.178.62:41241 shutting down...
I20260812 06:20:14.061452 16072 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:14.061591 16072 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:14.061650 16072 tablet_replica.cc:333] T 00000000000000000000000000000000 P f124cb4fe05b434abe5ae6daf7f69663: stopping tablet replica
I20260812 06:20:14.073484 16072 master.cc:584] Master@127.15.178.62:41241 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5205 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10270 ms total)

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