[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:41.939093  5344 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.56.62:36451
I20260812 06:18:41.940060  5344 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:41.940661  5344 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.946913  5356 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.946995  5344 server_base.cc:1061] running on GCE node
W20260812 06:18:41.946933  5352 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.947194  5354 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.947671  5344 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.947777  5344 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.947820  5344 hybrid_clock.cc:648] HybridClock initialized: now 1786515521947818 us; error 0 us; skew 500 ppm
I20260812 06:18:41.949527  5344 webserver.cc:533] Webserver started at http://127.5.56.62:33779/ using document root <none> and password file <none>
I20260812 06:18:41.950062  5344 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.950124  5344 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.950345  5344 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.951992  5344 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/master-0-root/instance:
uuid: "9515bab40d94440783b11ef6c52d1fc5"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-xt4k"
I20260812 06:18:41.955319  5344 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:18:41.957312  5364 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.958240  5344 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:41.958345  5344 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/master-0-root
uuid: "9515bab40d94440783b11ef6c52d1fc5"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-xt4k"
I20260812 06:18:41.958432  5344 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:41.972894  5344 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.973485  5344 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:41.973646  5344 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.980530  5344 rpc_server.cc:307] RPC server started. Bound to: 127.5.56.62:36451
I20260812 06:18:41.980527  5456 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.56.62:36451 every 8 connection(s)
I20260812 06:18:41.982673  5460 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.987879  5460 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: Bootstrap starting.
I20260812 06:18:41.990203  5460 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.991050  5460 log.cc:826] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:41.992690  5460 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: No bootstrap required, opened a new log
I20260812 06:18:41.995303  5460 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER }
I20260812 06:18:41.995456  5460 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.995501  5460 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9515bab40d94440783b11ef6c52d1fc5, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.996166  5460 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [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: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER }
I20260812 06:18:41.996362  5460 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.996428  5460 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.996551  5460 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.997268  5460 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER }
I20260812 06:18:41.997684  5460 leader_election.cc:304] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [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: 9515bab40d94440783b11ef6c52d1fc5; no voters: 
I20260812 06:18:41.997959  5460 leader_election.cc:290] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.998068  5471 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.998281  5471 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 1 LEADER]: Becoming Leader. State: Replica: 9515bab40d94440783b11ef6c52d1fc5, State: Running, Role: LEADER
I20260812 06:18:41.998677  5471 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [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: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER }
I20260812 06:18:41.998868  5460 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:42.000476  5473 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9515bab40d94440783b11ef6c52d1fc5. Latest consensus state: current_term: 1 leader_uuid: "9515bab40d94440783b11ef6c52d1fc5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER } }
I20260812 06:18:42.000452  5472 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9515bab40d94440783b11ef6c52d1fc5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9515bab40d94440783b11ef6c52d1fc5" member_type: VOTER } }
I20260812 06:18:42.000587  5472 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.000587  5473 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:42.000941  5493 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:42.001005  5344 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:42.003090  5493 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:42.007771  5493 catalog_manager.cc:1383] Generated new cluster ID: 60c43761c8b94e0d84f2482d33d5e7ea
I20260812 06:18:42.007834  5493 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:42.034729  5493 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:42.035642  5493 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:42.042474  5493 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: Generated new TSK 0
I20260812 06:18:42.043077  5493 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:42.065866  5344 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:42.068789  5504 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.068850  5344 server_base.cc:1061] running on GCE node
W20260812 06:18:42.068897  5508 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.068869  5510 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:42.069208  5344 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.069254  5344 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:42.069269  5344 hybrid_clock.cc:648] HybridClock initialized: now 1786515522069269 us; error 0 us; skew 500 ppm
I20260812 06:18:42.070092  5344 webserver.cc:533] Webserver started at http://127.5.56.1:43913/ using document root <none> and password file <none>
I20260812 06:18:42.070243  5344 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.070288  5344 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.070362  5344 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.070739  5344 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/instance:
uuid: "b49471cc51e749f1aa42142bfb75ccdb"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-xt4k"
I20260812 06:18:42.072103  5344 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:18:42.073036  5515 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.073273  5344 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:42.073339  5344 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root
uuid: "b49471cc51e749f1aa42142bfb75ccdb"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-xt4k"
I20260812 06:18:42.073406  5344 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:42.105204  5344 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.105613  5344 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.106048  5344 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:42.106863  5344 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:42.106916  5344 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.106961  5344 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:42.106990  5344 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.113193  5344 rpc_server.cc:307] RPC server started. Bound to: 127.5.56.1:38329
I20260812 06:18:42.113263  5627 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.56.1:38329 every 8 connection(s)
I20260812 06:18:42.125480  5628 heartbeater.cc:344] Connected to a master server at 127.5.56.62:36451
I20260812 06:18:42.125717  5628 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:42.126180  5628 heartbeater.cc:507] Master 127.5.56.62:36451 requested a full tablet report, sending...
I20260812 06:18:42.127552  5394 ts_manager.cc:194] Registered new tserver with Master: b49471cc51e749f1aa42142bfb75ccdb (127.5.56.1:38329)
I20260812 06:18:42.128098  5344 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014308627s
I20260812 06:18:42.128960  5394 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57398
I20260812 06:18:42.138216  5394 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57402:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:42.151378  5571 tablet_service.cc:1511] Processing CreateTablet for tablet 5a265cffb6ef45cfa74680b5429f8cf5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=47119aef753944c2be853d5c74a7f2d7]), partition=
I20260812 06:18:42.151885  5571 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5a265cffb6ef45cfa74680b5429f8cf5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.154070  5653 tablet_bootstrap.cc:492] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Bootstrap starting.
I20260812 06:18:42.154999  5653 tablet_bootstrap.cc:654] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.155948  5653 tablet_bootstrap.cc:492] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: No bootstrap required, opened a new log
I20260812 06:18:42.156041  5653 ts_tablet_manager.cc:1403] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:42.156448  5653 raft_consensus.cc:359] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b49471cc51e749f1aa42142bfb75ccdb" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 38329 } }
I20260812 06:18:42.156548  5653 raft_consensus.cc:385] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.156579  5653 raft_consensus.cc:740] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b49471cc51e749f1aa42142bfb75ccdb, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.156704  5653 consensus_queue.cc:260] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [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: "b49471cc51e749f1aa42142bfb75ccdb" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 38329 } }
I20260812 06:18:42.156772  5653 raft_consensus.cc:399] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.156814  5653 raft_consensus.cc:493] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.156862  5653 raft_consensus.cc:3060] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.157487  5653 raft_consensus.cc:515] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b49471cc51e749f1aa42142bfb75ccdb" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 38329 } }
I20260812 06:18:42.157616  5653 leader_election.cc:304] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [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: b49471cc51e749f1aa42142bfb75ccdb; no voters: 
I20260812 06:18:42.157785  5653 leader_election.cc:290] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.157881  5658 raft_consensus.cc:2804] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.158106  5653 ts_tablet_manager.cc:1434] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.158106  5658 raft_consensus.cc:697] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 1 LEADER]: Becoming Leader. State: Replica: b49471cc51e749f1aa42142bfb75ccdb, State: Running, Role: LEADER
I20260812 06:18:42.158514  5628 heartbeater.cc:499] Master 127.5.56.62:36451 was elected leader, sending a full tablet report...
I20260812 06:18:42.158730  5658 consensus_queue.cc:237] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [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: "b49471cc51e749f1aa42142bfb75ccdb" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 38329 } }
I20260812 06:18:42.161226  5394 catalog_manager.cc:5719] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb reported cstate change: term changed from 0 to 1, leader changed from <none> to b49471cc51e749f1aa42142bfb75ccdb (127.5.56.1). New cstate: current_term: 1 leader_uuid: "b49471cc51e749f1aa42142bfb75ccdb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b49471cc51e749f1aa42142bfb75ccdb" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 38329 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.218992  5344 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.012s	sys 0.010s
I20260812 06:18:42.364259  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=19.054940
I20260812 06:18:42.561978  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.197s	user 0.132s	sys 0.064s Metrics: {"bytes_written":16327853,"cfile_init":1,"compiler_manager_pool.queue_time_us":180,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":853,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48825,"lbm_writes_lt_1ms":865,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":274304,"thread_start_us":92,"threads_started":1,"update_count":1990}
I20260812 06:18:42.563606  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5): free 20743880 bytes of WAL
I20260812 06:18:42.563928  5526 log_reader.cc:385] T 5a265cffb6ef45cfa74680b5429f8cf5: removed 2 log segments from log reader
I20260812 06:18:42.564005  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000001 (ops 1-6)
I20260812 06:18:42.564072  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000002 (ops 7-11)
I20260812 06:18:42.568955  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:42.569298  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=6.157687
I20260812 06:18:42.586531  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":7876888,"delete_count":0,"lbm_write_time_us":6987,"lbm_writes_lt_1ms":195,"reinsert_count":0,"update_count":960}
I20260812 06:18:42.586941  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5): 16821646 bytes on disk
I20260812 06:18:42.587461  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.587823  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:42.782658  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.195s	user 0.150s	sys 0.036s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28507858,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":598,"lbm_read_time_us":12939,"lbm_reads_lt_1ms":654,"lbm_write_time_us":32184,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"thread_start_us":286,"threads_started":5,"update_count":2950}
I20260812 06:18:42.783135  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:42.844312  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.061s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20876,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.844820  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:42.855430  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.855935  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.018309  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.162s	user 0.111s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":10735,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28780,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:43.018827  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:43.049242  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.030s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12856,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.049827  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.064576  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4967,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.065128  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.196583  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.131s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":873,"lbm_read_time_us":8960,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22240,"lbm_writes_lt_1ms":443,"mutex_wait_us":333,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:18:43.197189  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:43.229108  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13418,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.229535  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.244179  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.244815  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.372759  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.128s	user 0.102s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":8291,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24515,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:18:43.373266  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:43.412289  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.039s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.412817  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.428056  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.428668  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.549160  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.120s	user 0.095s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1026,"lbm_read_time_us":8314,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23737,"lbm_writes_lt_1ms":443,"mutex_wait_us":248,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:43.549805  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:43.594944  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.045s	user 0.016s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16905,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.595456  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.605775  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.606208  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.740504  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.134s	user 0.082s	sys 0.052s 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":346,"lbm_read_time_us":10286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21534,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:18:43.741389  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:43.790381  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.049s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.790853  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.801177  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.801817  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:43.834617  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1247,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2007,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:43.835580  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5): free 124710302 bytes of WAL
I20260812 06:18:43.835829  5526 log_reader.cc:385] T 5a265cffb6ef45cfa74680b5429f8cf5: removed 12 log segments from log reader
I20260812 06:18:43.835880  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000003 (ops 12-16)
I20260812 06:18:43.835919  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000004 (ops 17-21)
I20260812 06:18:43.835953  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000005 (ops 22-26)
I20260812 06:18:43.835984  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000006 (ops 27-31)
I20260812 06:18:43.836015  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000007 (ops 32-36)
I20260812 06:18:43.836045  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000008 (ops 37-41)
I20260812 06:18:43.836076  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000009 (ops 42-46)
I20260812 06:18:43.836107  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000010 (ops 47-51)
I20260812 06:18:43.836136  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000011 (ops 52-56)
I20260812 06:18:43.836166  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000012 (ops 57-61)
I20260812 06:18:43.836197  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000013 (ops 62-66)
I20260812 06:18:43.836227  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000014 (ops 67-71)
I20260812 06:18:43.857267  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:43.857663  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5): 472 bytes on disk
I20260812 06:18:43.858121  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.858681  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.881299  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.022s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.881817  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:43.896970  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.897543  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:44.095073  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.197s	user 0.117s	sys 0.074s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":557,"lbm_read_time_us":14700,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32769,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:44.096635  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:44.148626  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.052s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.149199  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.166483  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.167111  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:44.332059  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.165s	user 0.096s	sys 0.067s 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":298,"lbm_read_time_us":12356,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29921,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:44.332806  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:44.375855  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.043s	user 0.017s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19717,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.376531  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.398499  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.022s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.398907  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.416137  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.017s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.416642  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:44.574467  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.158s	user 0.096s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":580,"lbm_read_time_us":11664,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27248,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:44.575084  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:44.609284  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.034s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14276,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.609982  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.636451  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.636950  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.647102  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.647671  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:44.806751  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.159s	user 0.117s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815804,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":517,"lbm_read_time_us":10397,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27512,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:18:44.807192  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:44.838723  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.031s	user 0.011s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13517,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.839389  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.863670  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.864113  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:44.873893  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.874327  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.020474  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.146s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1591,"lbm_read_time_us":10836,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28590,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:45.023371  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:45.060381  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.036s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15691,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.061287  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:45.079090  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6535,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.079631  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.199321  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.119s	user 0.103s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":6918,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23850,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.199949  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=10.126437
I20260812 06:18:45.243220  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.043s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15656,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.247008  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:45.258576  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.259460  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.291011  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1130,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1356,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:45.291747  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5): free 128867468 bytes of WAL
I20260812 06:18:45.291980  5526 log_reader.cc:385] T 5a265cffb6ef45cfa74680b5429f8cf5: removed 13 log segments from log reader
I20260812 06:18:45.292025  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000015 (ops 72-76)
I20260812 06:18:45.292055  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000016 (ops 77-81)
I20260812 06:18:45.292088  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000017 (ops 82-86)
I20260812 06:18:45.292127  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000018 (ops 87-90)
I20260812 06:18:45.292162  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000019 (ops 91-95)
I20260812 06:18:45.292181  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000020 (ops 96-100)
I20260812 06:18:45.292213  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000021 (ops 101-105)
I20260812 06:18:45.292246  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000022 (ops 106-110)
I20260812 06:18:45.292280  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000023 (ops 111-114)
I20260812 06:18:45.292313  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000024 (ops 115-119)
I20260812 06:18:45.292366  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000025 (ops 120-124)
I20260812 06:18:45.292397  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000026 (ops 125-128)
I20260812 06:18:45.292428  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000027 (ops 129-133)
I20260812 06:18:45.316246  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.024s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:45.316745  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=3.181125
I20260812 06:18:45.334722  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4964173,"delete_count":0,"lbm_write_time_us":7529,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:18:45.335142  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:45.343393  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":2889,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:45.343842  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5): 473 bytes on disk
I20260812 06:18:45.344424  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.345031  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.519840  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.175s	user 0.109s	sys 0.060s 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":381,"lbm_read_time_us":11857,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35584,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:45.520386  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:45.571641  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.051s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22085,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.572122  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:45.589267  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.589793  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.737167  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.147s	user 0.097s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":624,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27146,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":61568,"update_count":2500}
I20260812 06:18:45.737660  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:45.798161  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.060s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.798679  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:45.813695  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.814421  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:45.966279  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.152s	user 0.091s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":509,"lbm_read_time_us":10624,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24777,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:45.966856  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:46.027951  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.061s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27442,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.028602  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.039793  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.040382  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:46.203449  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.162s	user 0.109s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":10988,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26800,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:18:46.204022  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=14.095187
I20260812 06:18:46.256524  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.052s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17360,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.257076  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.267494  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.267935  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:46.433524  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.165s	user 0.108s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1050,"lbm_read_time_us":11474,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26818,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:46.434273  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:46.472221  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.038s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15945,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.472901  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.487702  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.488381  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:46.632658  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.144s	user 0.081s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":7764,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20490,"lbm_writes_lt_1ms":443,"mutex_wait_us":209,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.633224  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=11.118625
I20260812 06:18:46.663113  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.030s	user 0.017s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12138,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.663635  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.686497  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.023s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4462,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.687037  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.701452  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.701956  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:46.731957  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushMRSOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.030s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1250,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1392,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:46.732704  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5): free 120553644 bytes of WAL
I20260812 06:18:46.732929  5526 log_reader.cc:385] T 5a265cffb6ef45cfa74680b5429f8cf5: removed 12 log segments from log reader
I20260812 06:18:46.732992  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000028 (ops 134-138)
I20260812 06:18:46.733035  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000029 (ops 139-142)
I20260812 06:18:46.733076  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000030 (ops 143-147)
I20260812 06:18:46.733110  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000031 (ops 148-152)
I20260812 06:18:46.733139  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000032 (ops 153-157)
I20260812 06:18:46.733167  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000033 (ops 158-162)
I20260812 06:18:46.733196  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000034 (ops 163-167)
I20260812 06:18:46.733223  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000035 (ops 168-172)
I20260812 06:18:46.733258  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000036 (ops 173-176)
I20260812 06:18:46.733286  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000037 (ops 177-181)
I20260812 06:18:46.733314  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000038 (ops 182-186)
I20260812 06:18:46.733341  5526 log.cc:1079] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/5a265cffb6ef45cfa74680b5429f8cf5/wal-000000039 (ops 187-191)
I20260812 06:18:46.758306  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: LogGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:46.758733  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=3.181125
I20260812 06:18:46.779089  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6751,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.779526  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5): 482 bytes on disk
I20260812 06:18:46.779903  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: UndoDeltaBlockGCOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.780458  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=2.188937
I20260812 06:18:46.797869  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: FlushDeltaMemStoresOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3210,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.798563  5632 maintenance_manager.cc:419] P b49471cc51e749f1aa42142bfb75ccdb: Scheduling MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5): perf score=1.000000
I20260812 06:18:46.888309  5344 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.669s	user 1.648s	sys 0.193s
I20260812 06:18:46.990793  5344 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.000s	sys 0.001s
I20260812 06:18:46.991384  5344 tablet_server.cc:179] TabletServer@127.5.56.1:0 shutting down...
I20260812 06:18:46.997365  5526 maintenance_manager.cc:643] P b49471cc51e749f1aa42142bfb75ccdb: MajorDeltaCompactionOp(5a265cffb6ef45cfa74680b5429f8cf5) complete. Timing: real 0.199s	user 0.134s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020846,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":573,"lbm_read_time_us":14858,"lbm_reads_lt_1ms":771,"lbm_write_time_us":30487,"lbm_writes_lt_1ms":743,"mutex_wait_us":269,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24832,"thread_start_us":65,"threads_started":1,"update_count":3500}
I20260812 06:18:46.999035  5344 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:47.000947  5344 tablet_replica.cc:333] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb: stopping tablet replica
I20260812 06:18:47.001170  5344 raft_consensus.cc:2243] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.001420  5344 raft_consensus.cc:2272] T 5a265cffb6ef45cfa74680b5429f8cf5 P b49471cc51e749f1aa42142bfb75ccdb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.018312  5344 tablet_server.cc:196] TabletServer@127.5.56.1:0 shutdown complete.
I20260812 06:18:47.054926  5344 master.cc:562] Master@127.5.56.62:36451 shutting down...
I20260812 06:18:47.058341  5344 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.058522  5344 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.058604  5344 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9515bab40d94440783b11ef6c52d1fc5: stopping tablet replica
I20260812 06:18:47.070837  5344 master.cc:584] Master@127.5.56.62:36451 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5205 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:47.156572  5344 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.56.62:42349
I20260812 06:18:47.156972  5344 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.158921  5684 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.158972  5344 server_base.cc:1061] running on GCE node
W20260812 06:18:47.159000  5690 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.159037  5687 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.159364  5344 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.159411  5344 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.159427  5344 hybrid_clock.cc:648] HybridClock initialized: now 1786515527159427 us; error 0 us; skew 500 ppm
I20260812 06:18:47.160291  5344 webserver.cc:533] Webserver started at http://127.5.56.62:44695/ using document root <none> and password file <none>
I20260812 06:18:47.160473  5344 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.160521  5344 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.160579  5344 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.160928  5344 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/master-0-root/instance:
uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-xt4k"
I20260812 06:18:47.162464  5344 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:47.163368  5702 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.163606  5344 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:47.163688  5344 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/master-0-root
uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-xt4k"
I20260812 06:18:47.163760  5344 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.175001  5344 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.175379  5344 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.179507  5344 rpc_server.cc:307] RPC server started. Bound to: 127.5.56.62:42349
I20260812 06:18:47.183761  5801 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.56.62:42349 every 8 connection(s)
I20260812 06:18:47.184206  5802 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.185967  5802 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6: Bootstrap starting.
I20260812 06:18:47.186748  5802 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.187711  5802 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6: No bootstrap required, opened a new log
I20260812 06:18:47.188110  5802 raft_consensus.cc:359] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER }
I20260812 06:18:47.188199  5802 raft_consensus.cc:385] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.188230  5802 raft_consensus.cc:740] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eee1b2156ae24a6ca172bbda0a7bc7d6, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.188400  5802 consensus_queue.cc:260] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [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: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER }
I20260812 06:18:47.188479  5802 raft_consensus.cc:399] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.188519  5802 raft_consensus.cc:493] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.188567  5802 raft_consensus.cc:3060] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.189222  5802 raft_consensus.cc:515] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER }
I20260812 06:18:47.189344  5802 leader_election.cc:304] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [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: eee1b2156ae24a6ca172bbda0a7bc7d6; no voters: 
I20260812 06:18:47.189512  5802 leader_election.cc:290] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.189610  5805 raft_consensus.cc:2804] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.189806  5805 raft_consensus.cc:697] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 1 LEADER]: Becoming Leader. State: Replica: eee1b2156ae24a6ca172bbda0a7bc7d6, State: Running, Role: LEADER
I20260812 06:18:47.189945  5802 sys_catalog.cc:565] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:47.189936  5805 consensus_queue.cc:237] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [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: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER }
I20260812 06:18:47.190372  5806 sys_catalog.cc:455] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER } }
I20260812 06:18:47.190400  5808 sys_catalog.cc:455] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader eee1b2156ae24a6ca172bbda0a7bc7d6. Latest consensus state: current_term: 1 leader_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eee1b2156ae24a6ca172bbda0a7bc7d6" member_type: VOTER } }
I20260812 06:18:47.190462  5806 sys_catalog.cc:458] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.190486  5808 sys_catalog.cc:458] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.190721  5811 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:47.191504  5811 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:47.191751  5344 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:47.193342  5811 catalog_manager.cc:1383] Generated new cluster ID: de0f5fcc085f412782ae214caef45bb1
I20260812 06:18:47.193401  5811 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:47.202638  5811 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:47.203229  5811 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:47.211535  5811 catalog_manager.cc:6092] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6: Generated new TSK 0
I20260812 06:18:47.211709  5811 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:47.224032  5344 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.225951  5845 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.225956  5840 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.226006  5841 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.226008  5344 server_base.cc:1061] running on GCE node
I20260812 06:18:47.226336  5344 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.226375  5344 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.226390  5344 hybrid_clock.cc:648] HybridClock initialized: now 1786515527226390 us; error 0 us; skew 500 ppm
I20260812 06:18:47.227180  5344 webserver.cc:533] Webserver started at http://127.5.56.1:35631/ using document root <none> and password file <none>
I20260812 06:18:47.227305  5344 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.227342  5344 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.227396  5344 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.227746  5344 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/instance:
uuid: "ad3bc47cdd9343b79f953a5a971993ad"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-xt4k"
I20260812 06:18:47.229139  5344 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:47.229949  5853 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.230154  5344 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:47.230219  5344 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root
uuid: "ad3bc47cdd9343b79f953a5a971993ad"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-xt4k"
I20260812 06:18:47.230284  5344 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.241528  5344 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.241885  5344 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.242156  5344 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:47.242619  5344 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:47.242656  5344 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.242698  5344 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:47.242726  5344 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.246729  5344 rpc_server.cc:307] RPC server started. Bound to: 127.5.56.1:34485
I20260812 06:18:47.247663  5971 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.56.1:34485 every 8 connection(s)
I20260812 06:18:47.254846  5972 heartbeater.cc:344] Connected to a master server at 127.5.56.62:42349
I20260812 06:18:47.254937  5972 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.255134  5972 heartbeater.cc:507] Master 127.5.56.62:42349 requested a full tablet report, sending...
I20260812 06:18:47.255733  5738 ts_manager.cc:194] Registered new tserver with Master: ad3bc47cdd9343b79f953a5a971993ad (127.5.56.1:34485)
I20260812 06:18:47.256266  5344 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008839972s
I20260812 06:18:47.256445  5738 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54718
I20260812 06:18:47.262836  5738 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54728:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:47.270946  5909 tablet_service.cc:1511] Processing CreateTablet for tablet 9c8cd09cd2f94e588217294c1c5c539f (DEFAULT_TABLE table=heavy-update-compaction-test [id=1d791c9c209944778150e8fd5eb3f221]), partition=
I20260812 06:18:47.271200  5909 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9c8cd09cd2f94e588217294c1c5c539f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.273090  6002 tablet_bootstrap.cc:492] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Bootstrap starting.
I20260812 06:18:47.273932  6002 tablet_bootstrap.cc:654] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.274917  6002 tablet_bootstrap.cc:492] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: No bootstrap required, opened a new log
I20260812 06:18:47.274991  6002 ts_tablet_manager.cc:1403] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:47.275352  6002 raft_consensus.cc:359] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3bc47cdd9343b79f953a5a971993ad" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 34485 } }
I20260812 06:18:47.275434  6002 raft_consensus.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.275463  6002 raft_consensus.cc:740] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad3bc47cdd9343b79f953a5a971993ad, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.275556  6002 consensus_queue.cc:260] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [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: "ad3bc47cdd9343b79f953a5a971993ad" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 34485 } }
I20260812 06:18:47.275614  6002 raft_consensus.cc:399] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.275640  6002 raft_consensus.cc:493] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.275673  6002 raft_consensus.cc:3060] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.276467  6002 raft_consensus.cc:515] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3bc47cdd9343b79f953a5a971993ad" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 34485 } }
I20260812 06:18:47.276593  6002 leader_election.cc:304] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [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: ad3bc47cdd9343b79f953a5a971993ad; no voters: 
I20260812 06:18:47.276741  6002 leader_election.cc:290] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.276852  6007 raft_consensus.cc:2804] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.277030  6002 ts_tablet_manager.cc:1434] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:47.277076  5972 heartbeater.cc:499] Master 127.5.56.62:42349 was elected leader, sending a full tablet report...
I20260812 06:18:47.277072  6007 raft_consensus.cc:697] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 1 LEADER]: Becoming Leader. State: Replica: ad3bc47cdd9343b79f953a5a971993ad, State: Running, Role: LEADER
I20260812 06:18:47.277251  6007 consensus_queue.cc:237] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [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: "ad3bc47cdd9343b79f953a5a971993ad" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 34485 } }
I20260812 06:18:47.278496  5738 catalog_manager.cc:5719] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad reported cstate change: term changed from 0 to 1, leader changed from <none> to ad3bc47cdd9343b79f953a5a971993ad (127.5.56.1). New cstate: current_term: 1 leader_uuid: "ad3bc47cdd9343b79f953a5a971993ad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad3bc47cdd9343b79f953a5a971993ad" member_type: VOTER last_known_addr { host: "127.5.56.1" port: 34485 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.336401  5344 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.014s	sys 0.008s
I20260812 06:18:47.498095  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=23.023690
I20260812 06:18:47.654917  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.157s	user 0.122s	sys 0.032s Metrics: {"bytes_written":13045918,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":776,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38208,"lbm_writes_lt_1ms":875,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1280,"update_count":1590}
I20260812 06:18:47.655488  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling LogGCOp(9c8cd09cd2f94e588217294c1c5c539f): free 20743880 bytes of WAL
I20260812 06:18:47.655699  5861 log_reader.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f: removed 2 log segments from log reader
I20260812 06:18:47.655743  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000001 (ops 1-6)
I20260812 06:18:47.655771  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000002 (ops 7-11)
I20260812 06:18:47.659387  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: LogGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:47.659701  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f): 20513813 bytes on disk
I20260812 06:18:47.660056  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.660486  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:47.683467  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.023s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:47.683933  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:47.697432  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4964,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.697926  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:47.873936  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.176s	user 0.122s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815777,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":706,"lbm_read_time_us":11357,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28223,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":299,"threads_started":5,"update_count":2500}
I20260812 06:18:47.874471  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:47.930750  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.056s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.931216  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:47.941231  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.941731  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:48.105751  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.164s	user 0.101s	sys 0.061s 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":291,"lbm_read_time_us":12474,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25745,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:48.106357  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:48.146485  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.040s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17823,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.147101  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:48.309473  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.162s	user 0.128s	sys 0.020s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":124,"lbm_read_time_us":10573,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22213,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":36608,"update_count":2000}
I20260812 06:18:48.310082  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:48.368124  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.055s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24395,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.368641  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:48.378566  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.379196  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:48.562415  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.183s	user 0.121s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":10705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26352,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:48.562928  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:48.613368  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.050s	user 0.031s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.613937  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:48.629683  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.630309  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:48.780501  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.150s	user 0.108s	sys 0.038s 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":522,"lbm_read_time_us":9953,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26688,"lbm_writes_lt_1ms":543,"mutex_wait_us":271,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:48.781080  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=11.118625
I20260812 06:18:48.820130  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":13251052,"delete_count":0,"lbm_write_time_us":16596,"lbm_writes_lt_1ms":326,"reinsert_count":0,"update_count":1615}
I20260812 06:18:48.820719  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.196750
I20260812 06:18:48.840188  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.019s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3567,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:18:48.840649  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:48.850586  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.851061  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:48.880209  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1454,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1495,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:48.880988  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling LogGCOp(9c8cd09cd2f94e588217294c1c5c539f): free 124710251 bytes of WAL
I20260812 06:18:48.881238  5861 log_reader.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f: removed 12 log segments from log reader
I20260812 06:18:48.881289  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000003 (ops 12-16)
I20260812 06:18:48.881330  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000004 (ops 17-21)
I20260812 06:18:48.881362  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000005 (ops 22-26)
I20260812 06:18:48.881387  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000006 (ops 27-31)
I20260812 06:18:48.881419  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000007 (ops 32-36)
I20260812 06:18:48.881479  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000008 (ops 37-41)
I20260812 06:18:48.881505  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000009 (ops 42-46)
I20260812 06:18:48.881536  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000010 (ops 47-51)
I20260812 06:18:48.881567  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000011 (ops 52-56)
I20260812 06:18:48.881597  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000012 (ops 57-61)
I20260812 06:18:48.881626  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000013 (ops 62-66)
I20260812 06:18:48.881656  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000014 (ops 67-71)
I20260812 06:18:48.905038  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: LogGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.024s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:18:48.905512  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f): 462 bytes on disk
I20260812 06:18:48.906109  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.906577  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=3.181125
I20260812 06:18:48.928979  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.929433  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:48.940243  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3676,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.940753  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:49.159646  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.219s	user 0.119s	sys 0.100s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020838,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":491,"lbm_read_time_us":16207,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36896,"lbm_writes_lt_1ms":743,"mutex_wait_us":33,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:49.160151  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=15.087375
I20260812 06:18:49.201472  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.041s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":18292,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:49.202009  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:49.225843  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.024s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6983,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.226333  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:49.391480  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.165s	user 0.115s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815672,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":11626,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25889,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:49.391952  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:49.445580  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.053s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.446206  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:49.460529  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.461022  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:49.637828  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.177s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":11960,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26071,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:49.638326  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:49.697705  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.059s	user 0.014s	sys 0.034s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":16642,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.698264  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:49.713551  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.714026  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:49.883948  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.170s	user 0.117s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":12508,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26585,"lbm_writes_lt_1ms":543,"mutex_wait_us":103,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:49.884447  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=11.118625
I20260812 06:18:49.913123  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.029s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":11947,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:49.913590  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:49.925698  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.926167  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.050359  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.124s	user 0.092s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1156,"dirs.run_cpu_time_us":603,"dirs.run_wall_time_us":2034,"lbm_read_time_us":8987,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22388,"lbm_writes_lt_1ms":443,"mutex_wait_us":282,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:18:50.050894  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=10.126437
I20260812 06:18:50.080065  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12387,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.080575  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:50.096539  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.096992  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.219425  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.122s	user 0.100s	sys 0.019s 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":135,"lbm_read_time_us":7029,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24297,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:50.219978  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=10.126437
I20260812 06:18:50.251296  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.031s	user 0.011s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11297,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.252224  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:50.268719  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.269263  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.296818  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.027s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":951,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1450,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:50.297523  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling LogGCOp(9c8cd09cd2f94e588217294c1c5c539f): free 112239365 bytes of WAL
I20260812 06:18:50.297756  5861 log_reader.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f: removed 11 log segments from log reader
I20260812 06:18:50.297804  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000015 (ops 72-76)
I20260812 06:18:50.297842  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000016 (ops 77-80)
I20260812 06:18:50.297873  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000017 (ops 81-85)
I20260812 06:18:50.297904  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000018 (ops 86-90)
I20260812 06:18:50.297932  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000019 (ops 91-95)
I20260812 06:18:50.297969  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000020 (ops 96-100)
I20260812 06:18:50.297999  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000021 (ops 101-105)
I20260812 06:18:50.298028  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000022 (ops 106-110)
I20260812 06:18:50.298058  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000023 (ops 111-115)
I20260812 06:18:50.298087  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000024 (ops 116-120)
I20260812 06:18:50.298116  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000025 (ops 121-125)
I20260812 06:18:50.319461  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: LogGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:50.319976  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=3.181125
I20260812 06:18:50.336078  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.336597  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling LogGCOp(9c8cd09cd2f94e588217294c1c5c539f): free 12017940 bytes of WAL
I20260812 06:18:50.336817  5861 log_reader.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f: removed 1 log segments from log reader
I20260812 06:18:50.336879  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000026 (ops 126-130)
I20260812 06:18:50.339471  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: LogGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:50.339810  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:50.354298  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5160,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.355855  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f): 463 bytes on disk
I20260812 06:18:50.356244  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.356763  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.518806  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.162s	user 0.103s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":642,"lbm_read_time_us":13155,"lbm_reads_lt_1ms":666,"lbm_write_time_us":29862,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":131,"threads_started":1,"update_count":3000}
I20260812 06:18:50.519505  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:50.569108  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.049s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21310,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.569613  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:50.587579  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.588111  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.742017  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.154s	user 0.107s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":937,"lbm_read_time_us":10233,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27005,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38144,"update_count":2500}
I20260812 06:18:50.742718  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:50.787567  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.045s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18907,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.788035  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:50.943573  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.155s	user 0.092s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":167,"lbm_read_time_us":9861,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26299,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:50.944139  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:50.989384  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.045s	user 0.024s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17484,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.989904  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.000746  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.001446  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.184835  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.183s	user 0.090s	sys 0.083s 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":253,"lbm_read_time_us":11163,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26370,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:18:51.185352  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:51.235103  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.050s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19597,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.235642  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.251154  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.251874  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.400703  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.149s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":581,"lbm_read_time_us":9333,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29336,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:51.401233  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=11.118625
I20260812 06:18:51.435278  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.034s	user 0.017s	sys 0.014s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14157,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:51.435791  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.448426  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3595,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.448982  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.567317  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.118s	user 0.074s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":506,"lbm_read_time_us":7152,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22895,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:18:51.567927  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=10.126437
I20260812 06:18:51.605331  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.037s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14836,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.605906  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.615651  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.616114  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.644033  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushMRSOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1503,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1453,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:51.644757  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling LogGCOp(9c8cd09cd2f94e588217294c1c5c539f): free 112692610 bytes of WAL
I20260812 06:18:51.644982  5861 log_reader.cc:385] T 9c8cd09cd2f94e588217294c1c5c539f: removed 11 log segments from log reader
I20260812 06:18:51.645047  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000027 (ops 131-135)
I20260812 06:18:51.645085  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000028 (ops 136-140)
I20260812 06:18:51.645107  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000029 (ops 141-145)
I20260812 06:18:51.645136  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000030 (ops 146-150)
I20260812 06:18:51.645169  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000031 (ops 151-155)
I20260812 06:18:51.645198  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000032 (ops 156-160)
I20260812 06:18:51.645226  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000033 (ops 161-165)
I20260812 06:18:51.645249  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000034 (ops 166-170)
I20260812 06:18:51.645270  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000035 (ops 171-175)
I20260812 06:18:51.645300  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000036 (ops 176-180)
I20260812 06:18:51.645331  5861 log.cc:1079] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: Deleting log segment in path: /tmp/dist-test-taskKz8dkv/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521928556-5344-0/minicluster-data/ts-0-root/wals/9c8cd09cd2f94e588217294c1c5c539f/wal-000000037 (ops 181-185)
I20260812 06:18:51.668771  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: LogGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:51.669157  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f): 462 bytes on disk
I20260812 06:18:51.669595  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: UndoDeltaBlockGCOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.670197  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=3.181125
I20260812 06:18:51.685261  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.015s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:51.685664  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.695003  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.695425  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.857151  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.162s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":537,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31862,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:51.857671  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=14.095187
I20260812 06:18:51.912858  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.055s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22815,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.913419  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=2.188937
I20260812 06:18:51.927052  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: FlushDeltaMemStoresOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.927596  5979 maintenance_manager.cc:419] P ad3bc47cdd9343b79f953a5a971993ad: Scheduling MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f): perf score=1.000000
I20260812 06:18:51.952565  5344 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.616s	user 1.730s	sys 0.157s
I20260812 06:18:52.019181  5344 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.001s	sys 0.000s
I20260812 06:18:52.019868  5344 tablet_server.cc:179] TabletServer@127.5.56.1:0 shutting down...
I20260812 06:18:52.070191  5861 maintenance_manager.cc:643] P ad3bc47cdd9343b79f953a5a971993ad: MajorDeltaCompactionOp(9c8cd09cd2f94e588217294c1c5c539f) complete. Timing: real 0.142s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":666,"lbm_read_time_us":11326,"lbm_reads_lt_1ms":560,"lbm_write_time_us":27712,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":116352,"update_count":2500}
I20260812 06:18:52.070854  5344 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.071084  5344 tablet_replica.cc:333] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad: stopping tablet replica
I20260812 06:18:52.071240  5344 raft_consensus.cc:2243] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.071383  5344 raft_consensus.cc:2272] T 9c8cd09cd2f94e588217294c1c5c539f P ad3bc47cdd9343b79f953a5a971993ad [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.084592  5344 tablet_server.cc:196] TabletServer@127.5.56.1:0 shutdown complete.
I20260812 06:18:52.115229  5344 master.cc:562] Master@127.5.56.62:42349 shutting down...
I20260812 06:18:52.118112  5344 raft_consensus.cc:2243] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.118294  5344 raft_consensus.cc:2272] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.118345  5344 tablet_replica.cc:333] T 00000000000000000000000000000000 P eee1b2156ae24a6ca172bbda0a7bc7d6: stopping tablet replica
I20260812 06:18:52.130767  5344 master.cc:584] Master@127.5.56.62:42349 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5060 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10267 ms total)

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