[==========] 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:59.978437  6246 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.25.190:34301
I20260812 06:18:59.979507  6246 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:59.980170  6246 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.987286  6254 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:59.987464  6246 server_base.cc:1061] running on GCE node
W20260812 06:18:59.987591  6252 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:59.987766  6251 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:59.988320  6246 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.988457  6246 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:59.988504  6246 hybrid_clock.cc:648] HybridClock initialized: now 1786515539988501 us; error 0 us; skew 500 ppm
I20260812 06:18:59.990557  6246 webserver.cc:533] Webserver started at http://127.6.25.190:41539/ using document root <none> and password file <none>
I20260812 06:18:59.991159  6246 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.991252  6246 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.991632  6246 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.993474  6246 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/master-0-root/instance:
uuid: "b5623f987d2046a79a261aa893bdd8f8"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-cbsf"
I20260812 06:18:59.997313  6246 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:59.999611  6262 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:19:00.001147  6246 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:00.001303  6246 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/master-0-root
uuid: "b5623f987d2046a79a261aa893bdd8f8"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-cbsf"
I20260812 06:19:00.001425  6246 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-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:19:00.015304  6246 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.016023  6246 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:19:00.016223  6246 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.024612  6246 rpc_server.cc:307] RPC server started. Bound to: 127.6.25.190:34301
I20260812 06:19:00.024641  6329 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.25.190:34301 every 8 connection(s)
I20260812 06:19:00.027171  6330 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:19:00.033313  6330 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: Bootstrap starting.
I20260812 06:19:00.035842  6330 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.036885  6330 log.cc:826] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:00.038753  6330 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: No bootstrap required, opened a new log
I20260812 06:19:00.041780  6330 raft_consensus.cc:359] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER }
I20260812 06:19:00.041957  6330 raft_consensus.cc:385] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.042006  6330 raft_consensus.cc:740] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b5623f987d2046a79a261aa893bdd8f8, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.042662  6330 consensus_queue.cc:260] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [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: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER }
I20260812 06:19:00.042809  6330 raft_consensus.cc:399] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.042850  6330 raft_consensus.cc:493] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.042945  6330 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.043767  6330 raft_consensus.cc:515] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER }
I20260812 06:19:00.044170  6330 leader_election.cc:304] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [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: b5623f987d2046a79a261aa893bdd8f8; no voters: 
I20260812 06:19:00.044454  6330 leader_election.cc:290] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.044652  6333 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.044951  6333 raft_consensus.cc:697] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 1 LEADER]: Becoming Leader. State: Replica: b5623f987d2046a79a261aa893bdd8f8, State: Running, Role: LEADER
I20260812 06:19:00.045373  6333 consensus_queue.cc:237] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [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: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER }
I20260812 06:19:00.045657  6330 sys_catalog.cc:565] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:00.047631  6335 sys_catalog.cc:455] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b5623f987d2046a79a261aa893bdd8f8. Latest consensus state: current_term: 1 leader_uuid: "b5623f987d2046a79a261aa893bdd8f8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER } }
I20260812 06:19:00.047606  6334 sys_catalog.cc:455] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b5623f987d2046a79a261aa893bdd8f8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5623f987d2046a79a261aa893bdd8f8" member_type: VOTER } }
I20260812 06:19:00.047789  6334 sys_catalog.cc:458] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.047789  6335 sys_catalog.cc:458] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:00.048195  6246 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:00.048525  6355 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:00.050933  6355 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:00.056068  6355 catalog_manager.cc:1383] Generated new cluster ID: f9b300d7924f43fcb021154d44842073
I20260812 06:19:00.056171  6355 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:00.068807  6355 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:00.069825  6355 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:00.080510  6355 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: Generated new TSK 0
I20260812 06:19:00.081327  6355 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:00.113389  6246 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:00.116395  6360 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:19:00.116544  6363 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:19:00.116663  6246 server_base.cc:1061] running on GCE node
W20260812 06:19:00.116853  6361 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:19:00.117075  6246 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:00.117156  6246 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:19:00.117195  6246 hybrid_clock.cc:648] HybridClock initialized: now 1786515540117194 us; error 0 us; skew 500 ppm
I20260812 06:19:00.118238  6246 webserver.cc:533] Webserver started at http://127.6.25.129:33313/ using document root <none> and password file <none>
I20260812 06:19:00.118434  6246 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:00.118494  6246 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:00.118636  6246 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:00.119065  6246 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/instance:
uuid: "63d5438508964cb7b46321971b2272ce"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-cbsf"
I20260812 06:19:00.120666  6246 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:00.121744  6370 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:19:00.121999  6246 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:00.122076  6246 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root
uuid: "63d5438508964cb7b46321971b2272ce"
format_stamp: "Formatted at 2026-08-12 06:19:00 on dist-test-slave-cbsf"
I20260812 06:19:00.122174  6246 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-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:19:00.133785  6246 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:00.134310  6246 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:00.134891  6246 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:00.135830  6246 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:00.135882  6246 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.135958  6246 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:00.136001  6246 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:00.143119  6246 rpc_server.cc:307] RPC server started. Bound to: 127.6.25.129:33053
I20260812 06:19:00.143147  6449 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.25.129:33053 every 8 connection(s)
I20260812 06:19:00.154320  6455 heartbeater.cc:344] Connected to a master server at 127.6.25.190:34301
I20260812 06:19:00.154615  6455 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:00.155138  6455 heartbeater.cc:507] Master 127.6.25.190:34301 requested a full tablet report, sending...
I20260812 06:19:00.156810  6283 ts_manager.cc:194] Registered new tserver with Master: 63d5438508964cb7b46321971b2272ce (127.6.25.129:33053)
I20260812 06:19:00.157262  6246 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013459545s
I20260812 06:19:00.158141  6283 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54248
I20260812 06:19:00.167318  6283 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54254:
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:19:00.181623  6407 tablet_service.cc:1511] Processing CreateTablet for tablet 4d22f41fd968426cba343ef1e2941648 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c5ad20d9004e46ee83d271844365501d]), partition=
I20260812 06:19:00.182163  6407 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4d22f41fd968426cba343ef1e2941648. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:00.184572  6470 tablet_bootstrap.cc:492] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Bootstrap starting.
I20260812 06:19:00.186079  6470 tablet_bootstrap.cc:654] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:00.187304  6470 tablet_bootstrap.cc:492] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: No bootstrap required, opened a new log
I20260812 06:19:00.187391  6470 ts_tablet_manager.cc:1403] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:00.187891  6470 raft_consensus.cc:359] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63d5438508964cb7b46321971b2272ce" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 33053 } }
I20260812 06:19:00.187997  6470 raft_consensus.cc:385] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:00.188071  6470 raft_consensus.cc:740] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 63d5438508964cb7b46321971b2272ce, State: Initialized, Role: FOLLOWER
I20260812 06:19:00.188246  6470 consensus_queue.cc:260] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [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: "63d5438508964cb7b46321971b2272ce" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 33053 } }
I20260812 06:19:00.188331  6470 raft_consensus.cc:399] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:00.188381  6470 raft_consensus.cc:493] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:00.188436  6470 raft_consensus.cc:3060] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:00.189399  6470 raft_consensus.cc:515] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63d5438508964cb7b46321971b2272ce" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 33053 } }
I20260812 06:19:00.189553  6470 leader_election.cc:304] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [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: 63d5438508964cb7b46321971b2272ce; no voters: 
I20260812 06:19:00.189867  6470 leader_election.cc:290] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:00.190165  6472 raft_consensus.cc:2804] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:00.190402  6472 raft_consensus.cc:697] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 1 LEADER]: Becoming Leader. State: Replica: 63d5438508964cb7b46321971b2272ce, State: Running, Role: LEADER
I20260812 06:19:00.190562  6455 heartbeater.cc:499] Master 127.6.25.190:34301 was elected leader, sending a full tablet report...
I20260812 06:19:00.190629  6472 consensus_queue.cc:237] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [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: "63d5438508964cb7b46321971b2272ce" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 33053 } }
I20260812 06:19:00.190402  6470 ts_tablet_manager.cc:1434] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:00.193729  6283 catalog_manager.cc:5719] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce reported cstate change: term changed from 0 to 1, leader changed from <none> to 63d5438508964cb7b46321971b2272ce (127.6.25.129). New cstate: current_term: 1 leader_uuid: "63d5438508964cb7b46321971b2272ce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63d5438508964cb7b46321971b2272ce" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 33053 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:00.271147  6246 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.021s	sys 0.012s
I20260812 06:19:00.394346  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushMRSOp(4d22f41fd968426cba343ef1e2941648): perf score=15.086190
I20260812 06:19:00.578541  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushMRSOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.184s	user 0.149s	sys 0.032s Metrics: {"bytes_written":12758765,"cfile_init":1,"compiler_manager_pool.queue_time_us":766,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":920,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43382,"lbm_writes_lt_1ms":668,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":200960,"thread_start_us":172,"threads_started":1,"update_count":1555}
I20260812 06:19:00.579957  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling LogGCOp(4d22f41fd968426cba343ef1e2941648): free 11976772 bytes of WAL
I20260812 06:19:00.580289  6379 log_reader.cc:385] T 4d22f41fd968426cba343ef1e2941648: removed 1 log segments from log reader
I20260812 06:19:00.580363  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000001 (ops 1-6)
I20260812 06:19:00.584031  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: LogGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:00.584424  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648): 12308958 bytes on disk
I20260812 06:19:00.585129  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.585714  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=3.181125
I20260812 06:19:00.603245  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":7282,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:19:00.603693  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=1.196750
I20260812 06:19:00.612053  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3048,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:00.612556  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:00.786124  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.173s	user 0.131s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733821,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":531,"lbm_read_time_us":14945,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28843,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"thread_start_us":330,"threads_started":5,"update_count":2500}
I20260812 06:19:00.786726  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:00.827765  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.041s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17650,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.828357  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:00.843911  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.844574  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:00.983351  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.139s	user 0.118s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":11483,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26795,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:00.984042  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:01.034595  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.050s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17395,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.035157  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.047326  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.048004  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:01.177196  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.129s	user 0.085s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":487,"lbm_read_time_us":11457,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24342,"lbm_writes_lt_1ms":443,"mutex_wait_us":107,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:01.177934  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:01.226238  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.048s	user 0.021s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16241,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.226902  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.238070  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.238721  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:01.397876  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.159s	user 0.127s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":13331,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26215,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:01.398372  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:01.450920  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.052s	user 0.040s	sys 0.001s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19308,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.451458  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.463646  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.464129  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:01.596854  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.133s	user 0.102s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":9961,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25985,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":153216,"update_count":2000}
I20260812 06:19:01.597548  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:01.639110  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.041s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15932,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.639636  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.652035  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.652737  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:01.775548  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.122s	user 0.090s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":8265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24038,"lbm_writes_lt_1ms":443,"mutex_wait_us":282,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.776527  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=10.126437
I20260812 06:19:01.829473  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.053s	user 0.017s	sys 0.035s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19584,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.830164  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.849166  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.849821  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushMRSOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:01.883787  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushMRSOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":366,"dirs.run_wall_time_us":1645,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1821,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:01.884680  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling LogGCOp(4d22f41fd968426cba343ef1e2941648): free 121006386 bytes of WAL
I20260812 06:19:01.885004  6379 log_reader.cc:385] T 4d22f41fd968426cba343ef1e2941648: removed 12 log segments from log reader
I20260812 06:19:01.885072  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000002 (ops 7-11)
I20260812 06:19:01.885126  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000003 (ops 12-16)
I20260812 06:19:01.885183  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000004 (ops 17-21)
I20260812 06:19:01.885223  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000005 (ops 22-26)
I20260812 06:19:01.885262  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000006 (ops 27-30)
I20260812 06:19:01.885300  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000007 (ops 31-35)
I20260812 06:19:01.885336  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000008 (ops 36-40)
I20260812 06:19:01.885375  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000009 (ops 41-45)
I20260812 06:19:01.885411  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000010 (ops 46-50)
I20260812 06:19:01.885448  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000011 (ops 51-55)
I20260812 06:19:01.885493  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000012 (ops 56-60)
I20260812 06:19:01.885529  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000013 (ops 61-65)
I20260812 06:19:01.915088  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: LogGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:01.915529  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648): 462 bytes on disk
I20260812 06:19:01.915975  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.916445  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=3.181125
I20260812 06:19:01.934391  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.018s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:01.934903  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:01.944950  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.945394  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:02.149533  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.204s	user 0.136s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":895,"lbm_read_time_us":13724,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34504,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:19:02.150344  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:02.209802  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.059s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":25860,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.210410  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:02.364811  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.154s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631188,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":387,"lbm_read_time_us":10428,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23751,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:02.365547  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:02.421144  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.055s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.421684  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:02.434535  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.435190  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:02.637797  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.202s	user 0.137s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1062,"lbm_read_time_us":13561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32345,"lbm_writes_lt_1ms":543,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:19:02.638588  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:02.704814  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.066s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":35674,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.705484  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:02.733932  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.028s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.734412  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:02.756296  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.022s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.757222  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:02.964720  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.207s	user 0.150s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836252,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":400,"lbm_read_time_us":15659,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33072,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":3000}
I20260812 06:19:02.965485  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:03.025439  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.060s	user 0.039s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24660,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.025971  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:03.040970  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.041509  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:03.232568  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.191s	user 0.146s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":13990,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31652,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:03.233316  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:03.287432  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.054s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23452,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.287971  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=3.181125
I20260812 06:19:03.318157  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.030s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4767,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.318768  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:03.329303  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.329797  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushMRSOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:03.363157  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushMRSOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":140,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1571,"drs_written":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1616,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:03.363945  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:03.572628  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.208s	user 0.111s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836244,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":326,"lbm_read_time_us":12869,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34793,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:03.573421  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling LogGCOp(4d22f41fd968426cba343ef1e2941648): free 116849572 bytes of WAL
I20260812 06:19:03.573704  6379 log_reader.cc:385] T 4d22f41fd968426cba343ef1e2941648: removed 12 log segments from log reader
I20260812 06:19:03.573750  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000014 (ops 66-70)
I20260812 06:19:03.573797  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000015 (ops 71-74)
I20260812 06:19:03.573833  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000016 (ops 75-79)
I20260812 06:19:03.573868  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000017 (ops 80-84)
I20260812 06:19:03.573909  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000018 (ops 85-88)
I20260812 06:19:03.573949  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000019 (ops 89-93)
I20260812 06:19:03.573999  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000020 (ops 94-98)
I20260812 06:19:03.574036  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000021 (ops 99-103)
I20260812 06:19:03.574076  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000022 (ops 104-108)
I20260812 06:19:03.574116  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000023 (ops 109-112)
I20260812 06:19:03.574158  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000024 (ops 113-117)
I20260812 06:19:03.574200  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000025 (ops 118-122)
I20260812 06:19:03.608157  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: LogGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:03.608805  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648): 447 bytes on disk
I20260812 06:19:03.609333  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.609994  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=20.048312
I20260812 06:19:03.686990  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.077s	user 0.042s	sys 0.024s Metrics: {"bytes_written":22440446,"delete_count":0,"lbm_write_time_us":32329,"lbm_writes_lt_1ms":550,"reinsert_count":0,"update_count":2735}
I20260812 06:19:03.687659  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=5.165500
I20260812 06:19:03.711714  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.024s	user 0.010s	sys 0.011s Metrics: {"bytes_written":6276948,"delete_count":0,"lbm_write_time_us":10255,"lbm_writes_lt_1ms":156,"reinsert_count":0,"update_count":765}
I20260812 06:19:03.712221  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:03.956135  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.244s	user 0.140s	sys 0.094s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32938551,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":714,"lbm_read_time_us":17684,"lbm_reads_lt_1ms":764,"lbm_write_time_us":43088,"lbm_writes_lt_1ms":743,"mutex_wait_us":377,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":3500}
I20260812 06:19:03.956840  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=18.063937
I20260812 06:19:04.018528  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.061s	user 0.038s	sys 0.019s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":26009,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.019060  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:04.032305  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.032920  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:04.252933  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.220s	user 0.152s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836142,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":876,"lbm_read_time_us":13803,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35850,"lbm_writes_lt_1ms":643,"mutex_wait_us":424,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":3000}
I20260812 06:19:04.253564  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=18.063937
I20260812 06:19:04.310956  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.057s	user 0.041s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24650,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.311492  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:04.324585  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.325137  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:04.507326  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.182s	user 0.121s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":13622,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36811,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:19:04.508014  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:04.556155  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20942,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.557044  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:04.574429  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.574970  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:04.728492  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.153s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"lbm_read_time_us":9892,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28461,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.729426  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=14.095187
I20260812 06:19:04.781953  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.052s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22252,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.782541  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushMRSOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:04.839051  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushMRSOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.056s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":135,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1806,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2460,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:04.839813  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling LogGCOp(4d22f41fd968426cba343ef1e2941648): free 111786419 bytes of WAL
I20260812 06:19:04.840061  6379 log_reader.cc:385] T 4d22f41fd968426cba343ef1e2941648: removed 11 log segments from log reader
I20260812 06:19:04.840107  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000026 (ops 123-126)
I20260812 06:19:04.840138  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000027 (ops 127-131)
I20260812 06:19:04.840204  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000028 (ops 132-136)
I20260812 06:19:04.840240  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000029 (ops 137-140)
I20260812 06:19:04.840281  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000030 (ops 141-145)
I20260812 06:19:04.840340  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000031 (ops 146-150)
I20260812 06:19:04.840394  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000032 (ops 151-155)
I20260812 06:19:04.840428  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000033 (ops 156-160)
I20260812 06:19:04.840463  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000034 (ops 161-165)
I20260812 06:19:04.840503  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000035 (ops 166-170)
I20260812 06:19:04.840541  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000036 (ops 171-175)
I20260812 06:19:04.866663  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: LogGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:04.867169  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=6.157687
I20260812 06:19:04.889642  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.022s	user 0.009s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9721,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:04.890193  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling LogGCOp(4d22f41fd968426cba343ef1e2941648): free 8767197 bytes of WAL
I20260812 06:19:04.890427  6379 log_reader.cc:385] T 4d22f41fd968426cba343ef1e2941648: removed 1 log segments from log reader
I20260812 06:19:04.890473  6379 log.cc:1079] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/4d22f41fd968426cba343ef1e2941648/wal-000000037 (ops 176-180)
I20260812 06:19:04.892295  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: LogGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:04.892724  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:04.907297  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.907909  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648): 462 bytes on disk
I20260812 06:19:04.908587  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: UndoDeltaBlockGCOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.909240  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:05.144622  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.235s	user 0.136s	sys 0.091s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938666,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":619,"lbm_read_time_us":18451,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42016,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:19:05.145443  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=18.063937
I20260812 06:19:05.218559  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.073s	user 0.040s	sys 0.026s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":31048,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.219123  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=3.181125
I20260812 06:19:05.232618  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4635978,"delete_count":0,"lbm_write_time_us":5587,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:19:05.233130  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648): perf score=2.188937
I20260812 06:19:05.244858  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: FlushDeltaMemStoresOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:19:05.245548  6456 maintenance_manager.cc:419] P 63d5438508964cb7b46321971b2272ce: Scheduling MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648): perf score=1.000000
I20260812 06:19:05.329631  6246 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.058s	user 1.855s	sys 0.148s
I20260812 06:19:05.420219  6246 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.001s	sys 0.000s
I20260812 06:19:05.421006  6246 tablet_server.cc:179] TabletServer@127.6.25.129:0 shutting down...
I20260812 06:19:05.433899  6379 maintenance_manager.cc:643] P 63d5438508964cb7b46321971b2272ce: MajorDeltaCompactionOp(4d22f41fd968426cba343ef1e2941648) complete. Timing: real 0.188s	user 0.147s	sys 0.040s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938657,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1182,"lbm_read_time_us":14755,"lbm_reads_lt_1ms":769,"lbm_write_time_us":38833,"lbm_writes_lt_1ms":743,"mutex_wait_us":394,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":3500}
I20260812 06:19:05.434688  6246 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:05.435134  6246 tablet_replica.cc:333] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce: stopping tablet replica
I20260812 06:19:05.435415  6246 raft_consensus.cc:2243] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.435695  6246 raft_consensus.cc:2272] T 4d22f41fd968426cba343ef1e2941648 P 63d5438508964cb7b46321971b2272ce [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.453706  6246 tablet_server.cc:196] TabletServer@127.6.25.129:0 shutdown complete.
I20260812 06:19:05.494246  6246 master.cc:562] Master@127.6.25.190:34301 shutting down...
I20260812 06:19:05.498037  6246 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.498222  6246 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.498277  6246 tablet_replica.cc:333] T 00000000000000000000000000000000 P b5623f987d2046a79a261aa893bdd8f8: stopping tablet replica
I20260812 06:19:05.511111  6246 master.cc:584] Master@127.6.25.190:34301 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5632 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:05.610843  6246 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.25.190:37589
I20260812 06:19:05.611364  6246 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:05.613646  6246 server_base.cc:1061] running on GCE node
W20260812 06:19:05.613732  6495 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:19:05.613622  6491 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:19:05.613731  6492 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:19:05.614144  6246 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.614193  6246 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:19:05.614209  6246 hybrid_clock.cc:648] HybridClock initialized: now 1786515545614208 us; error 0 us; skew 500 ppm
I20260812 06:19:05.615136  6246 webserver.cc:533] Webserver started at http://127.6.25.190:42981/ using document root <none> and password file <none>
I20260812 06:19:05.615281  6246 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.615325  6246 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.615386  6246 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.615752  6246 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/master-0-root/instance:
uuid: "2405d0ae191b4ff9891ab36bd783b542"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-cbsf"
I20260812 06:19:05.617463  6246 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:05.618462  6500 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:19:05.618819  6246 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:05.618889  6246 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/master-0-root
uuid: "2405d0ae191b4ff9891ab36bd783b542"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-cbsf"
I20260812 06:19:05.618983  6246 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-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:19:05.659570  6246 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.660079  6246 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.665010  6246 rpc_server.cc:307] RPC server started. Bound to: 127.6.25.190:37589
I20260812 06:19:05.667234  6565 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.25.190:37589 every 8 connection(s)
I20260812 06:19:05.674300  6566 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:19:05.690217  6566 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542: Bootstrap starting.
I20260812 06:19:05.691255  6566 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.692497  6566 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542: No bootstrap required, opened a new log
I20260812 06:19:05.693035  6566 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER }
I20260812 06:19:05.693137  6566 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.693197  6566 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2405d0ae191b4ff9891ab36bd783b542, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.693375  6566 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [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: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER }
I20260812 06:19:05.693449  6566 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.693507  6566 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.693573  6566 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.694403  6566 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER }
I20260812 06:19:05.694547  6566 leader_election.cc:304] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [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: 2405d0ae191b4ff9891ab36bd783b542; no voters: 
I20260812 06:19:05.694794  6566 leader_election.cc:290] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.694988  6569 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.695240  6569 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 1 LEADER]: Becoming Leader. State: Replica: 2405d0ae191b4ff9891ab36bd783b542, State: Running, Role: LEADER
I20260812 06:19:05.695331  6566 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:05.695428  6569 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [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: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER }
I20260812 06:19:05.695921  6571 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2405d0ae191b4ff9891ab36bd783b542. Latest consensus state: current_term: 1 leader_uuid: "2405d0ae191b4ff9891ab36bd783b542" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER } }
I20260812 06:19:05.695905  6570 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2405d0ae191b4ff9891ab36bd783b542" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2405d0ae191b4ff9891ab36bd783b542" member_type: VOTER } }
I20260812 06:19:05.696022  6571 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.696038  6570 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:05.696297  6580 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:05.697467  6580 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:05.697719  6246 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:05.699445  6580 catalog_manager.cc:1383] Generated new cluster ID: 490e121aff3a43eb9e5e1f801fcf2df7
I20260812 06:19:05.699505  6580 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:05.733042  6580 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:05.733762  6580 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:05.740327  6580 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542: Generated new TSK 0
I20260812 06:19:05.740623  6580 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:05.762933  6246 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:05.765797  6594 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:19:05.765868  6596 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:19:05.765959  6246 server_base.cc:1061] running on GCE node
W20260812 06:19:05.765913  6593 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:19:05.766433  6246 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:05.766492  6246 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:19:05.766510  6246 hybrid_clock.cc:648] HybridClock initialized: now 1786515545766509 us; error 0 us; skew 500 ppm
I20260812 06:19:05.767705  6246 webserver.cc:533] Webserver started at http://127.6.25.129:35531/ using document root <none> and password file <none>
I20260812 06:19:05.768025  6246 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:05.768079  6246 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:05.768194  6246 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:05.768770  6246 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/instance:
uuid: "a9d3021976ca4a4bacd273cb56ff966a"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-cbsf"
I20260812 06:19:05.770529  6246 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:05.771734  6601 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:19:05.772145  6246 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:05.772271  6246 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root
uuid: "a9d3021976ca4a4bacd273cb56ff966a"
format_stamp: "Formatted at 2026-08-12 06:19:05 on dist-test-slave-cbsf"
I20260812 06:19:05.772393  6246 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-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:19:05.779242  6246 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:05.779752  6246 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:05.780100  6246 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:05.780647  6246 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:05.780740  6246 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.780809  6246 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:05.780846  6246 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:05.785925  6246 rpc_server.cc:307] RPC server started. Bound to: 127.6.25.129:41863
I20260812 06:19:05.786016  6677 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.25.129:41863 every 8 connection(s)
I20260812 06:19:05.795595  6678 heartbeater.cc:344] Connected to a master server at 127.6.25.190:37589
I20260812 06:19:05.795724  6678 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:05.795959  6678 heartbeater.cc:507] Master 127.6.25.190:37589 requested a full tablet report, sending...
I20260812 06:19:05.796886  6519 ts_manager.cc:194] Registered new tserver with Master: a9d3021976ca4a4bacd273cb56ff966a (127.6.25.129:41863)
I20260812 06:19:05.797688  6246 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011221689s
I20260812 06:19:05.797951  6519 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50406
I20260812 06:19:05.806581  6519 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50420:
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:19:05.816334  6634 tablet_service.cc:1511] Processing CreateTablet for tablet 0b7f5a6e23044f9d934cf70559a9196c (DEFAULT_TABLE table=heavy-update-compaction-test [id=4fb84d55d29d4a0b87e30fbaedb461c4]), partition=
I20260812 06:19:05.816673  6634 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0b7f5a6e23044f9d934cf70559a9196c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:05.819188  6695 tablet_bootstrap.cc:492] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Bootstrap starting.
I20260812 06:19:05.820205  6695 tablet_bootstrap.cc:654] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:05.821591  6695 tablet_bootstrap.cc:492] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: No bootstrap required, opened a new log
I20260812 06:19:05.821710  6695 ts_tablet_manager.cc:1403] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:05.822185  6695 raft_consensus.cc:359] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9d3021976ca4a4bacd273cb56ff966a" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 41863 } }
I20260812 06:19:05.822283  6695 raft_consensus.cc:385] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:05.822305  6695 raft_consensus.cc:740] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a9d3021976ca4a4bacd273cb56ff966a, State: Initialized, Role: FOLLOWER
I20260812 06:19:05.822444  6695 consensus_queue.cc:260] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [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: "a9d3021976ca4a4bacd273cb56ff966a" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 41863 } }
I20260812 06:19:05.822530  6695 raft_consensus.cc:399] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:05.822566  6695 raft_consensus.cc:493] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:05.822633  6695 raft_consensus.cc:3060] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:05.823550  6695 raft_consensus.cc:515] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9d3021976ca4a4bacd273cb56ff966a" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 41863 } }
I20260812 06:19:05.823675  6695 leader_election.cc:304] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [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: a9d3021976ca4a4bacd273cb56ff966a; no voters: 
I20260812 06:19:05.823849  6695 leader_election.cc:290] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:05.824002  6698 raft_consensus.cc:2804] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:05.824183  6695 ts_tablet_manager.cc:1434] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:05.824219  6678 heartbeater.cc:499] Master 127.6.25.190:37589 was elected leader, sending a full tablet report...
I20260812 06:19:05.824240  6698 raft_consensus.cc:697] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 1 LEADER]: Becoming Leader. State: Replica: a9d3021976ca4a4bacd273cb56ff966a, State: Running, Role: LEADER
I20260812 06:19:05.824445  6698 consensus_queue.cc:237] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [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: "a9d3021976ca4a4bacd273cb56ff966a" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 41863 } }
I20260812 06:19:05.826154  6518 catalog_manager.cc:5719] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a reported cstate change: term changed from 0 to 1, leader changed from <none> to a9d3021976ca4a4bacd273cb56ff966a (127.6.25.129). New cstate: current_term: 1 leader_uuid: "a9d3021976ca4a4bacd273cb56ff966a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a9d3021976ca4a4bacd273cb56ff966a" member_type: VOTER last_known_addr { host: "127.6.25.129" port: 41863 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:05.889153  6246 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.012s	sys 0.012s
I20260812 06:19:06.037086  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=19.054940
I20260812 06:19:06.193356  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.156s	user 0.111s	sys 0.040s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":933,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39047,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:06.194098  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling LogGCOp(0b7f5a6e23044f9d934cf70559a9196c): free 20743880 bytes of WAL
I20260812 06:19:06.194406  6608 log_reader.cc:385] T 0b7f5a6e23044f9d934cf70559a9196c: removed 2 log segments from log reader
I20260812 06:19:06.194483  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000001 (ops 1-6)
I20260812 06:19:06.194527  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000002 (ops 7-11)
I20260812 06:19:06.201205  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: LogGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:19:06.201825  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:06.223093  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.021s	user 0.011s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.223675  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c): 16411395 bytes on disk
I20260812 06:19:06.224084  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.224597  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:06.389194  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.164s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":568,"lbm_read_time_us":12253,"lbm_reads_lt_1ms":460,"lbm_write_time_us":27192,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":306,"threads_started":5,"update_count":2000}
I20260812 06:19:06.389853  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:06.451574  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.062s	user 0.046s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.452139  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:06.464223  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.464833  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:06.636826  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.172s	user 0.118s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":11945,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32595,"lbm_writes_lt_1ms":543,"mutex_wait_us":105,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26624,"update_count":2500}
I20260812 06:19:06.637588  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=13.103000
I20260812 06:19:06.686342  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":14645856,"delete_count":0,"lbm_write_time_us":21583,"lbm_writes_lt_1ms":360,"reinsert_count":0,"update_count":1785}
I20260812 06:19:06.686981  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.196750
I20260812 06:19:06.698226  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.011s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2174483,"delete_count":0,"lbm_write_time_us":2693,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:19:06.698676  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:06.854490  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.156s	user 0.105s	sys 0.050s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21082467,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":12304,"lbm_reads_lt_1ms":474,"lbm_write_time_us":26089,"lbm_writes_lt_1ms":453,"mutex_wait_us":52,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":2050}
I20260812 06:19:06.855065  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:06.909389  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.054s	user 0.044s	sys 0.009s Metrics: {"bytes_written":15999664,"delete_count":0,"lbm_write_time_us":23962,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:19:06.910038  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:06.941546  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.031s	user 0.018s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.942030  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:07.134065  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.192s	user 0.120s	sys 0.065s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24364451,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":884,"lbm_read_time_us":13315,"lbm_reads_lt_1ms":554,"lbm_write_time_us":29533,"lbm_writes_lt_1ms":533,"mutex_wait_us":365,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2450}
I20260812 06:19:07.134756  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:07.189471  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.055s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23695,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.190095  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:07.204542  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.205214  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:07.403728  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.198s	user 0.148s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1419,"lbm_read_time_us":11315,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34150,"lbm_writes_lt_1ms":543,"mutex_wait_us":445,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:19:07.404539  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:07.459849  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.055s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23484,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.460450  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:07.474326  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.474871  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:07.504031  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1482,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:07.504627  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling LogGCOp(0b7f5a6e23044f9d934cf70559a9196c): free 112239318 bytes of WAL
I20260812 06:19:07.504894  6608 log_reader.cc:385] T 0b7f5a6e23044f9d934cf70559a9196c: removed 11 log segments from log reader
I20260812 06:19:07.504967  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000003 (ops 12-16)
I20260812 06:19:07.505023  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000004 (ops 17-21)
I20260812 06:19:07.505080  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000005 (ops 22-26)
I20260812 06:19:07.505120  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000006 (ops 27-31)
I20260812 06:19:07.505156  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000007 (ops 32-36)
I20260812 06:19:07.505193  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000008 (ops 37-41)
I20260812 06:19:07.505229  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000009 (ops 42-46)
I20260812 06:19:07.505266  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000010 (ops 47-51)
I20260812 06:19:07.505302  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000011 (ops 52-56)
I20260812 06:19:07.505338  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000012 (ops 57-60)
I20260812 06:19:07.505374  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000013 (ops 61-65)
I20260812 06:19:07.534478  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: LogGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:07.535022  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=3.181125
I20260812 06:19:07.562544  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.027s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7363,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.563115  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c): 447 bytes on disk
I20260812 06:19:07.563573  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.564100  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:07.575546  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.576037  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:07.838567  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.262s	user 0.147s	sys 0.111s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":531,"lbm_read_time_us":18170,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40664,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:07.839366  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=18.063937
I20260812 06:19:07.912894  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.073s	user 0.023s	sys 0.039s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33072,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.913425  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:07.926708  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.927170  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:08.168936  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.242s	user 0.152s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":812,"lbm_read_time_us":19787,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37055,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":3000}
I20260812 06:19:08.169600  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:08.224426  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.055s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25293,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.225028  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:08.240445  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.240972  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:08.430362  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.189s	user 0.134s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":446,"lbm_read_time_us":14827,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32582,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:19:08.431066  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:08.497988  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.067s	user 0.035s	sys 0.025s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21691,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.498601  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:08.510404  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4573,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.510967  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:08.700891  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.190s	user 0.116s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":13705,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31548,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:08.701555  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:08.769049  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.067s	user 0.040s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22659,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.769997  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:08.782737  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.783325  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:09.009696  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.226s	user 0.118s	sys 0.092s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":15524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35441,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:19:09.010427  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:09.074743  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.064s	user 0.027s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26329,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.075426  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:09.090859  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.091429  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:09.124295  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.033s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1644,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1559,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:09.125113  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling LogGCOp(0b7f5a6e23044f9d934cf70559a9196c): free 120553382 bytes of WAL
I20260812 06:19:09.125466  6608 log_reader.cc:385] T 0b7f5a6e23044f9d934cf70559a9196c: removed 12 log segments from log reader
I20260812 06:19:09.125550  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000014 (ops 66-70)
I20260812 06:19:09.125615  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000015 (ops 71-74)
I20260812 06:19:09.125661  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000016 (ops 75-79)
I20260812 06:19:09.125707  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000017 (ops 80-84)
I20260812 06:19:09.125749  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000018 (ops 85-88)
I20260812 06:19:09.125794  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000019 (ops 89-93)
I20260812 06:19:09.125838  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000020 (ops 94-98)
I20260812 06:19:09.125882  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000021 (ops 99-103)
I20260812 06:19:09.125941  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000022 (ops 104-108)
I20260812 06:19:09.125985  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000023 (ops 109-113)
I20260812 06:19:09.126034  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000024 (ops 114-118)
I20260812 06:19:09.126082  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000025 (ops 119-123)
I20260812 06:19:09.158123  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: LogGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:09.158564  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c): 447 bytes on disk
I20260812 06:19:09.159195  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.159914  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=4.173312
I20260812 06:19:09.176529  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":5702609,"delete_count":0,"lbm_write_time_us":6830,"lbm_writes_lt_1ms":142,"reinsert_count":0,"update_count":695}
I20260812 06:19:09.177340  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.196750
I20260812 06:19:09.189620  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":2502679,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":64,"reinsert_count":0,"update_count":305}
I20260812 06:19:09.190124  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:09.465106  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.275s	user 0.196s	sys 0.070s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979714,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2317,"lbm_read_time_us":18331,"lbm_reads_lt_1ms":766,"lbm_write_time_us":43474,"lbm_writes_lt_1ms":743,"mutex_wait_us":1559,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:19:09.466006  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=18.063937
I20260812 06:19:09.539999  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.074s	user 0.020s	sys 0.041s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30074,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.540601  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:09.552423  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.553094  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:09.764379  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.211s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1117,"lbm_read_time_us":15638,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35814,"lbm_writes_lt_1ms":643,"mutex_wait_us":323,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":3000}
I20260812 06:19:09.765298  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=15.087375
I20260812 06:19:09.817592  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.052s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":23254,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:09.818334  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:09.835958  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6149,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.836503  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:10.026515  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.190s	user 0.141s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774674,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1172,"lbm_read_time_us":14959,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29991,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:19:10.027369  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=15.087375
I20260812 06:19:10.085283  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.058s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20363,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:10.086184  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:10.105051  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6470,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.105729  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:10.298983  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.193s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":12100,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33984,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:10.299665  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:10.361955  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.062s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20893,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.362599  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:10.374122  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.374634  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:10.577888  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.203s	user 0.143s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":13135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30725,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:19:10.578706  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:10.628545  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.050s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19721,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.629150  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:10.650218  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.021s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.650884  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:10.679819  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushMRSOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.029s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1316,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1504,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":3328}
I20260812 06:19:10.680598  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling LogGCOp(0b7f5a6e23044f9d934cf70559a9196c): free 111786481 bytes of WAL
I20260812 06:19:10.680873  6608 log_reader.cc:385] T 0b7f5a6e23044f9d934cf70559a9196c: removed 11 log segments from log reader
I20260812 06:19:10.680934  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000026 (ops 124-128)
I20260812 06:19:10.680975  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000027 (ops 129-132)
I20260812 06:19:10.681023  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000028 (ops 133-137)
I20260812 06:19:10.681047  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000029 (ops 138-142)
I20260812 06:19:10.681070  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000030 (ops 143-147)
I20260812 06:19:10.681100  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000031 (ops 148-152)
I20260812 06:19:10.681133  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000032 (ops 153-157)
I20260812 06:19:10.681169  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000033 (ops 158-162)
I20260812 06:19:10.681198  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000034 (ops 163-166)
I20260812 06:19:10.681227  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000035 (ops 167-171)
I20260812 06:19:10.681255  6608 log.cc:1079] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: Deleting log segment in path: /tmp/dist-test-taskJHqAyV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515539967048-6246-0/minicluster-data/ts-0-root/wals/0b7f5a6e23044f9d934cf70559a9196c/wal-000000036 (ops 172-176)
I20260812 06:19:10.710000  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: LogGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:10.710585  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c): 447 bytes on disk
I20260812 06:19:10.711122  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: UndoDeltaBlockGCOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.711926  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:10.739569  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.027s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":500}
I20260812 06:19:10.740069  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:10.751624  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.752151  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:11.019507  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.267s	user 0.184s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":863,"lbm_read_time_us":16912,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41045,"lbm_writes_lt_1ms":743,"mutex_wait_us":373,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:19:11.020457  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=18.063937
I20260812 06:19:11.093209  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.073s	user 0.032s	sys 0.036s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":33845,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.093827  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=2.188937
I20260812 06:19:11.106448  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.107033  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:11.292275  6246 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.403s	user 1.950s	sys 0.199s
I20260812 06:19:11.333736  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.226s	user 0.135s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":15183,"lbm_reads_lt_1ms":668,"lbm_write_time_us":39134,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3000}
I20260812 06:19:11.334381  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=14.095187
I20260812 06:19:11.377463  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: FlushDeltaMemStoresOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.043s	user 0.034s	sys 0.009s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.378010  6679 maintenance_manager.cc:419] P a9d3021976ca4a4bacd273cb56ff966a: Scheduling MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c): perf score=1.000000
I20260812 06:19:11.404909  6246 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.003s	sys 0.000s
I20260812 06:19:11.405540  6246 tablet_server.cc:179] TabletServer@127.6.25.129:0 shutting down...
I20260812 06:19:11.520929  6608 maintenance_manager.cc:643] P a9d3021976ca4a4bacd273cb56ff966a: MajorDeltaCompactionOp(0b7f5a6e23044f9d934cf70559a9196c) complete. Timing: real 0.143s	user 0.097s	sys 0.046s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":444,"lbm_read_time_us":11974,"lbm_reads_lt_1ms":467,"lbm_write_time_us":29167,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.521816  6246 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:11.522123  6246 tablet_replica.cc:333] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a: stopping tablet replica
I20260812 06:19:11.522258  6246 raft_consensus.cc:2243] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:11.522475  6246 raft_consensus.cc:2272] T 0b7f5a6e23044f9d934cf70559a9196c P a9d3021976ca4a4bacd273cb56ff966a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:11.526558  6246 tablet_server.cc:196] TabletServer@127.6.25.129:0 shutdown complete.
I20260812 06:19:11.560333  6246 master.cc:562] Master@127.6.25.190:37589 shutting down...
I20260812 06:19:11.563977  6246 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:11.564203  6246 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:11.564298  6246 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2405d0ae191b4ff9891ab36bd783b542: stopping tablet replica
I20260812 06:19:11.577157  6246 master.cc:584] Master@127.6.25.190:37589 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6070 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11704 ms total)

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