[==========] 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:17:57.256319   751 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.187.254:40873
I20260812 06:17:57.257421   751 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:17:57.258088   751 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.265161   758 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:17:57.265213   759 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:17:57.265388   751 server_base.cc:1061] running on GCE node
W20260812 06:17:57.265502   761 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:17:57.266065   751 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.266158   751 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:17:57.266189   751 hybrid_clock.cc:648] HybridClock initialized: now 1786515477266188 us; error 0 us; skew 500 ppm
I20260812 06:17:57.268175   751 webserver.cc:533] Webserver started at http://127.0.187.254:33289/ using document root <none> and password file <none>
I20260812 06:17:57.268740   751 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.268805   751 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.269021   751 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.270706   751 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/master-0-root/instance:
uuid: "f9939d6e90204c85a2fc0dda4f083978"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-2w3w"
I20260812 06:17:57.274425   751 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:17:57.276791   766 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:17:57.277882   751 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:57.277990   751 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/master-0-root
uuid: "f9939d6e90204c85a2fc0dda4f083978"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-2w3w"
I20260812 06:17:57.278144   751 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-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:17:57.311896   751 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.312651   751 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:17:57.312870   751 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.321519   751 rpc_server.cc:307] RPC server started. Bound to: 127.0.187.254:40873
I20260812 06:17:57.321575   831 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.187.254:40873 every 8 connection(s)
I20260812 06:17:57.323925   832 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:17:57.329677   832 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: Bootstrap starting.
I20260812 06:17:57.332131   832 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.333089   832 log.cc:826] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:57.334911   832 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: No bootstrap required, opened a new log
I20260812 06:17:57.337785   832 raft_consensus.cc:359] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER }
I20260812 06:17:57.337956   832 raft_consensus.cc:385] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.338032   832 raft_consensus.cc:740] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f9939d6e90204c85a2fc0dda4f083978, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.338654   832 consensus_queue.cc:260] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [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: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER }
I20260812 06:17:57.338795   832 raft_consensus.cc:399] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.338838   832 raft_consensus.cc:493] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.338987   832 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.339802   832 raft_consensus.cc:515] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER }
I20260812 06:17:57.340255   832 leader_election.cc:304] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [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: f9939d6e90204c85a2fc0dda4f083978; no voters: 
I20260812 06:17:57.340600   832 leader_election.cc:290] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.340853   835 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.341132   835 raft_consensus.cc:697] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 1 LEADER]: Becoming Leader. State: Replica: f9939d6e90204c85a2fc0dda4f083978, State: Running, Role: LEADER
I20260812 06:17:57.341508   835 consensus_queue.cc:237] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [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: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER }
I20260812 06:17:57.341606   832 sys_catalog.cc:565] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:57.343511   838 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f9939d6e90204c85a2fc0dda4f083978. Latest consensus state: current_term: 1 leader_uuid: "f9939d6e90204c85a2fc0dda4f083978" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER } }
I20260812 06:17:57.343554   837 sys_catalog.cc:455] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f9939d6e90204c85a2fc0dda4f083978" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f9939d6e90204c85a2fc0dda4f083978" member_type: VOTER } }
I20260812 06:17:57.343649   838 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.343655   837 sys_catalog.cc:458] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.344048   751 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:57.345956   852 catalog_manager.cc:1594] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:57.346020   852 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:57.346107   851 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:57.346849   851 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:57.352015   851 catalog_manager.cc:1383] Generated new cluster ID: 9745af3b8c924fcfb985da940caae048
I20260812 06:17:57.352104   851 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:57.366222   851 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:57.367478   851 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:57.375725   851 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: Generated new TSK 0
I20260812 06:17:57.376470   851 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:57.408957   751 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.411799   856 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:17:57.411832   859 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:17:57.411850   857 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:17:57.412552   751 server_base.cc:1061] running on GCE node
I20260812 06:17:57.412750   751 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.412788   751 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:17:57.412806   751 hybrid_clock.cc:648] HybridClock initialized: now 1786515477412805 us; error 0 us; skew 500 ppm
I20260812 06:17:57.413784   751 webserver.cc:533] Webserver started at http://127.0.187.193:41219/ using document root <none> and password file <none>
I20260812 06:17:57.413995   751 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.414045   751 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.414158   751 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.414597   751 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/instance:
uuid: "6e31a03c16444105a22cd205599a9f34"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-2w3w"
I20260812 06:17:57.416661   751 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:57.417732   864 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:17:57.417990   751 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:57.418067   751 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root
uuid: "6e31a03c16444105a22cd205599a9f34"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-2w3w"
I20260812 06:17:57.418171   751 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-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:17:57.423520   751 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.423993   751 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.424494   751 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:57.425410   751 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:57.425464   751 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.425535   751 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:57.425575   751 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.432876   751 rpc_server.cc:307] RPC server started. Bound to: 127.0.187.193:43221
I20260812 06:17:57.432888   939 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.187.193:43221 every 8 connection(s)
I20260812 06:17:57.447777   940 heartbeater.cc:344] Connected to a master server at 127.0.187.254:40873
I20260812 06:17:57.448112   940 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:57.448621   940 heartbeater.cc:507] Master 127.0.187.254:40873 requested a full tablet report, sending...
I20260812 06:17:57.450131   788 ts_manager.cc:194] Registered new tserver with Master: 6e31a03c16444105a22cd205599a9f34 (127.0.187.193:43221)
I20260812 06:17:57.450424   751 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016843023s
I20260812 06:17:57.451716   788 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54722
I20260812 06:17:57.460147   788 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54732:
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:17:57.474146   894 tablet_service.cc:1511] Processing CreateTablet for tablet 207943bf69f54b419a1c46572ba92f50 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bfb3d3fc92a6473fb018e64a12b9fccb]), partition=
I20260812 06:17:57.474674   894 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 207943bf69f54b419a1c46572ba92f50. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.477043   955 tablet_bootstrap.cc:492] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Bootstrap starting.
I20260812 06:17:57.478204   955 tablet_bootstrap.cc:654] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.479595   955 tablet_bootstrap.cc:492] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: No bootstrap required, opened a new log
I20260812 06:17:57.479715   955 ts_tablet_manager.cc:1403] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:57.480319   955 raft_consensus.cc:359] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e31a03c16444105a22cd205599a9f34" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 43221 } }
I20260812 06:17:57.480450   955 raft_consensus.cc:385] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.480486   955 raft_consensus.cc:740] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6e31a03c16444105a22cd205599a9f34, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.480634   955 consensus_queue.cc:260] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [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: "6e31a03c16444105a22cd205599a9f34" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 43221 } }
I20260812 06:17:57.480728   955 raft_consensus.cc:399] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.480765   955 raft_consensus.cc:493] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.480822   955 raft_consensus.cc:3060] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.481810   955 raft_consensus.cc:515] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e31a03c16444105a22cd205599a9f34" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 43221 } }
I20260812 06:17:57.482044   955 leader_election.cc:304] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [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: 6e31a03c16444105a22cd205599a9f34; no voters: 
I20260812 06:17:57.482254   955 leader_election.cc:290] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.482414   957 raft_consensus.cc:2804] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.482595   955 ts_tablet_manager.cc:1434] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:57.482681   957 raft_consensus.cc:697] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 1 LEADER]: Becoming Leader. State: Replica: 6e31a03c16444105a22cd205599a9f34, State: Running, Role: LEADER
I20260812 06:17:57.482887   957 consensus_queue.cc:237] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [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: "6e31a03c16444105a22cd205599a9f34" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 43221 } }
I20260812 06:17:57.483062   940 heartbeater.cc:499] Master 127.0.187.254:40873 was elected leader, sending a full tablet report...
I20260812 06:17:57.486049   788 catalog_manager.cc:5719] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6e31a03c16444105a22cd205599a9f34 (127.0.187.193). New cstate: current_term: 1 leader_uuid: "6e31a03c16444105a22cd205599a9f34" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e31a03c16444105a22cd205599a9f34" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 43221 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:57.557555   751 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.026s	sys 0.004s
I20260812 06:17:57.684269   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushMRSOp(207943bf69f54b419a1c46572ba92f50): perf score=15.086190
I20260812 06:17:57.845041   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushMRSOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.160s	user 0.115s	sys 0.040s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":343,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1173,"drs_written":1,"lbm_read_time_us":151,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40476,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":140,"threads_started":1,"update_count":1500}
I20260812 06:17:57.846081   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50): 12308959 bytes on disk
I20260812 06:17:57.846654   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.847204   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:57.859747   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.003s	sys 0.002s Metrics: {"bytes_written":1189881,"delete_count":0,"lbm_write_time_us":1408,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:17:57.860400   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling LogGCOp(207943bf69f54b419a1c46572ba92f50): free 11976772 bytes of WAL
I20260812 06:17:57.860781   869 log_reader.cc:385] T 207943bf69f54b419a1c46572ba92f50: removed 1 log segments from log reader
I20260812 06:17:57.860921   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000001 (ops 1-6)
I20260812 06:17:57.864807   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: LogGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:57.865346   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=1.196750
I20260812 06:17:57.877941   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":4568,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:57.878634   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:58.038487   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.160s	user 0.124s	sys 0.032s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631339,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":795,"lbm_read_time_us":14399,"lbm_reads_lt_1ms":469,"lbm_write_time_us":27820,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":328,"threads_started":5,"update_count":2000}
I20260812 06:17:58.039266   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:58.086853   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.047s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18499,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.087409   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:58.100736   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.101388   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:58.233203   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.132s	user 0.109s	sys 0.023s 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":233,"lbm_read_time_us":10619,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27050,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:17:58.233822   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:58.288074   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.054s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19890,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.288642   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:58.302439   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.303109   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:58.444597   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.141s	user 0.121s	sys 0.020s 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":185,"lbm_read_time_us":8836,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29263,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:17:58.445188   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:58.503973   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.059s	user 0.030s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20350,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.504817   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:58.517115   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.517693   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:58.676314   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.158s	user 0.114s	sys 0.040s 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":872,"lbm_read_time_us":12613,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27134,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:58.676849   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:58.730058   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.053s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16933,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.730672   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:58.743016   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.743641   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:58.875968   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.132s	user 0.116s	sys 0.015s 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":1172,"lbm_read_time_us":8908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27092,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:58.876696   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:58.917333   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.040s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15104,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.917937   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:58.934942   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.935809   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.077930   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.142s	user 0.105s	sys 0.036s 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":682,"lbm_read_time_us":10618,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28739,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:59.078529   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:17:59.131340   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.053s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20411,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:59.131832   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:59.144169   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.144717   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushMRSOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.177282   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushMRSOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.032s	user 0.029s	sys 0.002s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":304,"dirs.run_wall_time_us":1482,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1971,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:59.178093   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling LogGCOp(207943bf69f54b419a1c46572ba92f50): free 121006427 bytes of WAL
I20260812 06:17:59.178330   869 log_reader.cc:385] T 207943bf69f54b419a1c46572ba92f50: removed 12 log segments from log reader
I20260812 06:17:59.178375   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000002 (ops 7-11)
I20260812 06:17:59.178427   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000003 (ops 12-16)
I20260812 06:17:59.178473   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000004 (ops 17-21)
I20260812 06:17:59.178517   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000005 (ops 22-26)
I20260812 06:17:59.178558   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000006 (ops 27-31)
I20260812 06:17:59.178622   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000007 (ops 32-36)
I20260812 06:17:59.178658   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000008 (ops 37-40)
I20260812 06:17:59.178701   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000009 (ops 41-45)
I20260812 06:17:59.178736   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000010 (ops 46-50)
I20260812 06:17:59.178774   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000011 (ops 51-55)
I20260812 06:17:59.178814   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000012 (ops 56-60)
I20260812 06:17:59.178857   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000013 (ops 61-65)
I20260812 06:17:59.209010   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: LogGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:59.209491   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50): 448 bytes on disk
I20260812 06:17:59.210204   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.210860   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=5.165500
I20260812 06:17:59.228539   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":6933327,"delete_count":0,"lbm_write_time_us":7407,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:17:59.229048   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.244982   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.016s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1271927,"delete_count":0,"lbm_write_time_us":2612,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:17:59.245532   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.439275   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.194s	user 0.166s	sys 0.025s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":246,"lbm_read_time_us":18711,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35464,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:59.443713   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:17:59.496315   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.052s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22628,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.496814   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:59.524662   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.028s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:17:59.525116   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:59.536198   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.536702   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.720008   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.183s	user 0.133s	sys 0.049s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836254,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":321,"lbm_read_time_us":13520,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39827,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:17:59.720690   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:17:59.771905   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22997,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.772504   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:17:59.790498   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.018s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.791226   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:17:59.955564   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.164s	user 0.118s	sys 0.039s 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":376,"lbm_read_time_us":11408,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29924,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:59.956324   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:00.025978   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.069s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25507,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.026582   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:00.039384   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.039888   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:00.233304   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.193s	user 0.112s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1074,"lbm_read_time_us":14944,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32844,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:18:00.234093   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:00.304646   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.070s	user 0.044s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.305321   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:00.317718   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.318204   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:00.506505   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.188s	user 0.130s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":14583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31112,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:00.507433   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=11.118625
I20260812 06:18:00.578529   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.070s	user 0.026s	sys 0.031s Metrics: {"bytes_written":13456167,"delete_count":0,"lbm_write_time_us":25254,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":330,"mutex_wait_us":173,"reinsert_count":0,"update_count":1640}
I20260812 06:18:00.579172   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=5.165500
I20260812 06:18:00.596572   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.017s	user 0.003s	sys 0.013s Metrics: {"bytes_written":7056408,"delete_count":0,"lbm_write_time_us":7457,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:18:00.597322   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushMRSOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:00.639719   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushMRSOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.042s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2124,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:00.640555   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling LogGCOp(207943bf69f54b419a1c46572ba92f50): free 112239323 bytes of WAL
I20260812 06:18:00.640808   869 log_reader.cc:385] T 207943bf69f54b419a1c46572ba92f50: removed 11 log segments from log reader
I20260812 06:18:00.640884   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000014 (ops 66-70)
I20260812 06:18:00.640945   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000015 (ops 71-75)
I20260812 06:18:00.641000   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000016 (ops 76-80)
I20260812 06:18:00.641095   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000017 (ops 81-85)
I20260812 06:18:00.641144   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000018 (ops 86-90)
I20260812 06:18:00.641192   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000019 (ops 91-95)
I20260812 06:18:00.641235   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000020 (ops 96-100)
I20260812 06:18:00.641279   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000021 (ops 101-104)
I20260812 06:18:00.641327   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000022 (ops 105-109)
I20260812 06:18:00.641366   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000023 (ops 110-114)
I20260812 06:18:00.641407   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000024 (ops 115-119)
I20260812 06:18:00.671255   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: LogGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:00.671697   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50): 447 bytes on disk
I20260812 06:18:00.672640   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.673297   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=3.181125
I20260812 06:18:00.689810   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4903,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:00.690277   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:00.701516   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.702075   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:00.939371   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.237s	user 0.180s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938784,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":948,"lbm_read_time_us":17811,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43300,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:18:00.940433   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:00.990039   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.049s	user 0.038s	sys 0.006s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21796,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.990685   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:01.003234   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.003859   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:01.197770   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.194s	user 0.119s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":13767,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32669,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27008,"update_count":2500}
I20260812 06:18:01.199029   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:01.257066   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.058s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22769,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.257695   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:01.276337   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.277098   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:01.462291   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.185s	user 0.131s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":13873,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32539,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:18:01.463112   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:01.528760   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.065s	user 0.031s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.529352   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:01.540868   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.011s	user 0.005s	sys 0.004s 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:18:01.541411   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:01.728828   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.187s	user 0.131s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":14208,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33735,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:01.730482   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=11.118625
I20260812 06:18:01.765974   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15591,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.766553   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:01.780953   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4868,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.781625   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:01.949065   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.167s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":11035,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25326,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:01.949744   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=11.118625
I20260812 06:18:01.983368   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.033s	user 0.010s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15189,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.984036   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:01.999889   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.000536   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:02.139029   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.138s	user 0.118s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":456,"lbm_read_time_us":10990,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26650,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:02.139706   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=10.126437
I20260812 06:18:02.187747   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.048s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18130,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.188251   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:02.200778   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.201576   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushMRSOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:02.234527   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushMRSOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193506,"cfile_init":1,"dirs.queue_time_us":119,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1859,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2289,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:02.235249   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling LogGCOp(207943bf69f54b419a1c46572ba92f50): free 121006665 bytes of WAL
I20260812 06:18:02.235513   869 log_reader.cc:385] T 207943bf69f54b419a1c46572ba92f50: removed 12 log segments from log reader
I20260812 06:18:02.235581   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000025 (ops 120-124)
I20260812 06:18:02.235618   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000026 (ops 125-128)
I20260812 06:18:02.235644   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000027 (ops 129-133)
I20260812 06:18:02.235670   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000028 (ops 134-138)
I20260812 06:18:02.235700   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000029 (ops 139-143)
I20260812 06:18:02.235729   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000030 (ops 144-148)
I20260812 06:18:02.235751   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000031 (ops 149-153)
I20260812 06:18:02.235772   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000032 (ops 154-158)
I20260812 06:18:02.235800   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000033 (ops 159-163)
I20260812 06:18:02.235834   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000034 (ops 164-168)
I20260812 06:18:02.235867   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000035 (ops 169-173)
I20260812 06:18:02.235894   869 log.cc:1079] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515477244712-751-0/minicluster-data/ts-0-root/wals/207943bf69f54b419a1c46572ba92f50/wal-000000036 (ops 174-178)
I20260812 06:18:02.271037   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: LogGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.036s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:18:02.271512   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50): 462 bytes on disk
I20260812 06:18:02.272199   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: UndoDeltaBlockGCOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.272814   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:02.295883   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.023s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6490,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.296356   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:02.307575   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.308068   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:02.491703   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.183s	user 0.158s	sys 0.023s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836376,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":854,"lbm_read_time_us":12194,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39140,"lbm_writes_lt_1ms":643,"mutex_wait_us":340,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:02.492533   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:02.550261   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.057s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25572,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.550887   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=2.188937
I20260812 06:18:02.565069   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.565680   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:02.735402   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.169s	user 0.139s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1496,"lbm_read_time_us":10865,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33803,"lbm_writes_lt_1ms":543,"mutex_wait_us":381,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32768,"update_count":2500}
I20260812 06:18:02.736177   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50): perf score=14.095187
I20260812 06:18:02.807636   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: FlushDeltaMemStoresOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.071s	user 0.037s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":31649,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.808194   941 maintenance_manager.cc:419] P 6e31a03c16444105a22cd205599a9f34: Scheduling MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50): perf score=1.000000
I20260812 06:18:02.816898   751 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.259s	user 1.906s	sys 0.147s
I20260812 06:18:02.889441   751 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.000s	sys 0.002s
I20260812 06:18:02.890172   751 tablet_server.cc:179] TabletServer@127.0.187.193:0 shutting down...
I20260812 06:18:02.949858   869 maintenance_manager.cc:643] P 6e31a03c16444105a22cd205599a9f34: MajorDeltaCompactionOp(207943bf69f54b419a1c46572ba92f50) complete. Timing: real 0.141s	user 0.093s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1065,"lbm_read_time_us":11926,"lbm_reads_lt_1ms":459,"lbm_write_time_us":25290,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2000}
I20260812 06:18:02.950632   751 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:02.951133   751 tablet_replica.cc:333] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34: stopping tablet replica
I20260812 06:18:02.951419   751 raft_consensus.cc:2243] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.951711   751 raft_consensus.cc:2272] T 207943bf69f54b419a1c46572ba92f50 P 6e31a03c16444105a22cd205599a9f34 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.968677   751 tablet_server.cc:196] TabletServer@127.0.187.193:0 shutdown complete.
I20260812 06:18:02.990226   751 master.cc:562] Master@127.0.187.254:40873 shutting down...
I20260812 06:18:02.994783   751 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.995064   751 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.995178   751 tablet_replica.cc:333] T 00000000000000000000000000000000 P f9939d6e90204c85a2fc0dda4f083978: stopping tablet replica
I20260812 06:18:03.007851   751 master.cc:584] Master@127.0.187.254:40873 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5867 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:03.123087   751 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.187.254:44689
I20260812 06:18:03.123606   751 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.125905   978 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.126017   981 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.126111   979 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.126180   751 server_base.cc:1061] running on GCE node
I20260812 06:18:03.126438   751 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.126511   751 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:03.126535   751 hybrid_clock.cc:648] HybridClock initialized: now 1786515483126534 us; error 0 us; skew 500 ppm
I20260812 06:18:03.127410   751 webserver.cc:533] Webserver started at http://127.0.187.254:39629/ using document root <none> and password file <none>
I20260812 06:18:03.127605   751 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.127658   751 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.127737   751 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.128124   751 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/master-0-root/instance:
uuid: "b5d4d6580331417e933181bb81793f64"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-2w3w"
I20260812 06:18:03.129675   751 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:03.130707   988 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.131081   751 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.131165   751 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/master-0-root
uuid: "b5d4d6580331417e933181bb81793f64"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-2w3w"
I20260812 06:18:03.131229   751 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.147958   751 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.148394   751 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.152606   751 rpc_server.cc:307] RPC server started. Bound to: 127.0.187.254:44689
I20260812 06:18:03.157320  1049 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.187.254:44689 every 8 connection(s)
I20260812 06:18:03.160818  1051 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.173884  1051 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64: Bootstrap starting.
I20260812 06:18:03.174785  1051 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.176013  1051 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64: No bootstrap required, opened a new log
I20260812 06:18:03.176438  1051 raft_consensus.cc:359] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5d4d6580331417e933181bb81793f64" member_type: VOTER }
I20260812 06:18:03.176551  1051 raft_consensus.cc:385] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.176601  1051 raft_consensus.cc:740] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b5d4d6580331417e933181bb81793f64, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.176776  1051 consensus_queue.cc:260] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [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: "b5d4d6580331417e933181bb81793f64" member_type: VOTER }
I20260812 06:18:03.176870  1051 raft_consensus.cc:399] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.176916  1051 raft_consensus.cc:493] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.176968  1051 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.177692  1051 raft_consensus.cc:515] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5d4d6580331417e933181bb81793f64" member_type: VOTER }
I20260812 06:18:03.177857  1051 leader_election.cc:304] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [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: b5d4d6580331417e933181bb81793f64; no voters: 
I20260812 06:18:03.178072  1051 leader_election.cc:290] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.178246  1054 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.178546  1051 sys_catalog.cc:565] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.178552  1054 raft_consensus.cc:697] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 1 LEADER]: Becoming Leader. State: Replica: b5d4d6580331417e933181bb81793f64, State: Running, Role: LEADER
I20260812 06:18:03.178757  1054 consensus_queue.cc:237] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [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: "b5d4d6580331417e933181bb81793f64" member_type: VOTER }
I20260812 06:18:03.179327  1056 sys_catalog.cc:455] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b5d4d6580331417e933181bb81793f64. Latest consensus state: current_term: 1 leader_uuid: "b5d4d6580331417e933181bb81793f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5d4d6580331417e933181bb81793f64" member_type: VOTER } }
I20260812 06:18:03.179417  1056 sys_catalog.cc:458] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.179625  1055 sys_catalog.cc:455] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b5d4d6580331417e933181bb81793f64" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5d4d6580331417e933181bb81793f64" member_type: VOTER } }
I20260812 06:18:03.179792  1055 sys_catalog.cc:458] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.180178  1062 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.181195  1062 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.181421   751 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.183230  1062 catalog_manager.cc:1383] Generated new cluster ID: f7b140f3573945069c8350898e79c9e8
I20260812 06:18:03.183290  1062 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.195811  1062 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.196377  1062 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.200898  1062 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64: Generated new TSK 0
I20260812 06:18:03.201069  1062 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:03.214170   751 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.216632  1079 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.216768  1075 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:03.216802   751 server_base.cc:1061] running on GCE node
W20260812 06:18:03.216701  1076 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.217118   751 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.217168   751 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:03.217185   751 hybrid_clock.cc:648] HybridClock initialized: now 1786515483217184 us; error 0 us; skew 500 ppm
I20260812 06:18:03.218124   751 webserver.cc:533] Webserver started at http://127.0.187.193:37953/ using document root <none> and password file <none>
I20260812 06:18:03.218272   751 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.218341   751 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.218408   751 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.218775   751 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/instance:
uuid: "31b1327de12340cc9b53f287795a6eb5"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-2w3w"
I20260812 06:18:03.220389   751 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.221427  1084 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.221732   751 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.221828   751 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root
uuid: "31b1327de12340cc9b53f287795a6eb5"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-2w3w"
I20260812 06:18:03.221954   751 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.266944   751 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.267434   751 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.267771   751 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:03.268254   751 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:03.268316   751 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.268375   751 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:03.268432   751 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.273387   751 rpc_server.cc:307] RPC server started. Bound to: 127.0.187.193:38449
I20260812 06:18:03.273453  1169 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.187.193:38449 every 8 connection(s)
I20260812 06:18:03.283350  1170 heartbeater.cc:344] Connected to a master server at 127.0.187.254:44689
I20260812 06:18:03.283495  1170 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:03.283774  1170 heartbeater.cc:507] Master 127.0.187.254:44689 requested a full tablet report, sending...
I20260812 06:18:03.284546  1005 ts_manager.cc:194] Registered new tserver with Master: 31b1327de12340cc9b53f287795a6eb5 (127.0.187.193:38449)
I20260812 06:18:03.284981   751 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011075343s
I20260812 06:18:03.285395  1005 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54216
I20260812 06:18:03.292783  1005 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54222:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:03.302845  1129 tablet_service.cc:1511] Processing CreateTablet for tablet 040452a29e1748c1870998276a74d2b6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=83f2bb496ce744eb80c5350f2674f140]), partition=
I20260812 06:18:03.303246  1129 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 040452a29e1748c1870998276a74d2b6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.305626  1183 tablet_bootstrap.cc:492] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Bootstrap starting.
I20260812 06:18:03.306648  1183 tablet_bootstrap.cc:654] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.307937  1183 tablet_bootstrap.cc:492] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: No bootstrap required, opened a new log
I20260812 06:18:03.308064  1183 ts_tablet_manager.cc:1403] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:03.308598  1183 raft_consensus.cc:359] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "31b1327de12340cc9b53f287795a6eb5" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 38449 } }
I20260812 06:18:03.308718  1183 raft_consensus.cc:385] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.308766  1183 raft_consensus.cc:740] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 31b1327de12340cc9b53f287795a6eb5, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.308929  1183 consensus_queue.cc:260] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [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: "31b1327de12340cc9b53f287795a6eb5" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 38449 } }
I20260812 06:18:03.309042  1183 raft_consensus.cc:399] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.309087  1183 raft_consensus.cc:493] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.309141  1183 raft_consensus.cc:3060] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.309957  1183 raft_consensus.cc:515] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "31b1327de12340cc9b53f287795a6eb5" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 38449 } }
I20260812 06:18:03.310122  1183 leader_election.cc:304] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [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: 31b1327de12340cc9b53f287795a6eb5; no voters: 
I20260812 06:18:03.310354  1183 leader_election.cc:290] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.310520  1186 raft_consensus.cc:2804] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.310715  1183 ts_tablet_manager.cc:1434] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:03.310732  1170 heartbeater.cc:499] Master 127.0.187.254:44689 was elected leader, sending a full tablet report...
I20260812 06:18:03.310804  1186 raft_consensus.cc:697] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 1 LEADER]: Becoming Leader. State: Replica: 31b1327de12340cc9b53f287795a6eb5, State: Running, Role: LEADER
I20260812 06:18:03.311007  1186 consensus_queue.cc:237] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [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: "31b1327de12340cc9b53f287795a6eb5" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 38449 } }
I20260812 06:18:03.312454  1005 catalog_manager.cc:5719] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 31b1327de12340cc9b53f287795a6eb5 (127.0.187.193). New cstate: current_term: 1 leader_uuid: "31b1327de12340cc9b53f287795a6eb5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "31b1327de12340cc9b53f287795a6eb5" member_type: VOTER last_known_addr { host: "127.0.187.193" port: 38449 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:03.376685   751 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.019s	sys 0.004s
I20260812 06:18:03.524482  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushMRSOp(040452a29e1748c1870998276a74d2b6): perf score=15.086190
I20260812 06:18:03.671627  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushMRSOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.147s	user 0.105s	sys 0.037s Metrics: {"bytes_written":11897250,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1039,"drs_written":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37978,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:18:03.672325  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling LogGCOp(040452a29e1748c1870998276a74d2b6): free 20743880 bytes of WAL
I20260812 06:18:03.672587  1089 log_reader.cc:385] T 040452a29e1748c1870998276a74d2b6: removed 2 log segments from log reader
I20260812 06:18:03.672647  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000001 (ops 1-6)
I20260812 06:18:03.672708  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000002 (ops 7-11)
I20260812 06:18:03.677381  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: LogGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:03.677781  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6): 12719216 bytes on disk
I20260812 06:18:03.678222  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.678620  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:03.698734  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.020s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.699277  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:03.852924  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.153s	user 0.109s	sys 0.039s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262037,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":12359,"lbm_reads_lt_1ms":450,"lbm_write_time_us":27089,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":341,"threads_started":5,"update_count":1950}
I20260812 06:18:03.853449  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=11.118625
I20260812 06:18:03.885602  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.032s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14144,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:03.886233  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:03.907109  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6901,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":450}
I20260812 06:18:03.907572  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:04.044621  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.137s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":8758,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26977,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:18:04.045410  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=10.126437
I20260812 06:18:04.092945  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.047s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18945,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.093421  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:04.107781  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.108525  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:04.263070  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.154s	user 0.107s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":12107,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30467,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:18:04.263880  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=10.126437
I20260812 06:18:04.320611  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.057s	user 0.023s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19843,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.321154  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:04.332366  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.332979  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:04.496851  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.164s	user 0.124s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":99,"lbm_read_time_us":12701,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24604,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:18:04.497646  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=10.126437
I20260812 06:18:04.546536  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.048s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22629,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.547405  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:04.562358  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.562922  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:04.697120  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.134s	user 0.095s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":8390,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26745,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:04.697825  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=10.126437
I20260812 06:18:04.736060  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16594,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.736743  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:04.759249  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.022s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.759811  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:04.905252  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.145s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":953,"lbm_read_time_us":10309,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27020,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:18:04.906039  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=11.118625
I20260812 06:18:04.939788  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.034s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14754,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:04.940332  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:04.955497  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5620,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.956035  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:05.098501  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.142s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":867,"lbm_read_time_us":11661,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25844,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:18:05.099390  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=10.126437
I20260812 06:18:05.164676  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.065s	user 0.025s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17650,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.165339  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:05.176646  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.177156  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushMRSOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:05.224015  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushMRSOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.047s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2401,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:05.224754  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling LogGCOp(040452a29e1748c1870998276a74d2b6): free 128867446 bytes of WAL
I20260812 06:18:05.225019  1089 log_reader.cc:385] T 040452a29e1748c1870998276a74d2b6: removed 13 log segments from log reader
I20260812 06:18:05.225067  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000003 (ops 12-16)
I20260812 06:18:05.225100  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000004 (ops 17-20)
I20260812 06:18:05.225168  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000005 (ops 21-25)
I20260812 06:18:05.225234  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000006 (ops 26-30)
I20260812 06:18:05.225281  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000007 (ops 31-35)
I20260812 06:18:05.225323  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000008 (ops 36-40)
I20260812 06:18:05.225368  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000009 (ops 41-44)
I20260812 06:18:05.225409  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000010 (ops 45-49)
I20260812 06:18:05.225451  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000011 (ops 50-54)
I20260812 06:18:05.225494  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000012 (ops 55-58)
I20260812 06:18:05.225540  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000013 (ops 59-63)
I20260812 06:18:05.225582  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000014 (ops 64-68)
I20260812 06:18:05.225625  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000015 (ops 69-73)
I20260812 06:18:05.259927  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: LogGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.035s	user 0.002s	sys 0.032s Metrics: {}
I20260812 06:18:05.260372  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=4.173312
I20260812 06:18:05.276082  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":6504,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:18:05.276638  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6): 483 bytes on disk
I20260812 06:18:05.277082  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.277551  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=1.196750
I20260812 06:18:05.290007  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4740,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:18:05.290796  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:05.527580  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.237s	user 0.139s	sys 0.097s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":357,"lbm_read_time_us":16176,"lbm_reads_lt_1ms":666,"lbm_write_time_us":41545,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:18:05.528411  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=15.087375
I20260812 06:18:05.587565  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.059s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23924,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:05.588052  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:05.599677  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.600184  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:05.610297  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.610770  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:05.836789  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.226s	user 0.153s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":480,"lbm_read_time_us":16444,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38635,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":3000}
I20260812 06:18:05.837555  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:05.883087  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.045s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.883708  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:05.901942  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.902581  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:06.100606  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.198s	user 0.154s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":14166,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33044,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:18:06.101302  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:06.162216  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.061s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20587,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.163158  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:06.175974  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.176506  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:06.380155  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.203s	user 0.121s	sys 0.081s 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":622,"lbm_read_time_us":15168,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33840,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:18:06.380834  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:06.455473  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.074s	user 0.031s	sys 0.043s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":30347,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.456077  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:06.467283  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.467779  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:06.663208  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.195s	user 0.125s	sys 0.066s 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":355,"lbm_read_time_us":14019,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31867,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:06.663887  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:06.723446  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.059s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23712,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.723948  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:06.746714  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.023s	user 0.003s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4586,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.747304  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushMRSOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:06.788419  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushMRSOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.041s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1513,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1981,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:06.789155  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling LogGCOp(040452a29e1748c1870998276a74d2b6): free 111786270 bytes of WAL
I20260812 06:18:06.789389  1089 log_reader.cc:385] T 040452a29e1748c1870998276a74d2b6: removed 11 log segments from log reader
I20260812 06:18:06.789467  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000016 (ops 74-78)
I20260812 06:18:06.789523  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000017 (ops 79-82)
I20260812 06:18:06.789578  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000018 (ops 83-87)
I20260812 06:18:06.789621  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000019 (ops 88-92)
I20260812 06:18:06.789667  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000020 (ops 93-97)
I20260812 06:18:06.789709  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000021 (ops 98-102)
I20260812 06:18:06.789748  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000022 (ops 103-107)
I20260812 06:18:06.789784  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000023 (ops 108-112)
I20260812 06:18:06.789825  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000024 (ops 113-116)
I20260812 06:18:06.789861  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000025 (ops 117-121)
I20260812 06:18:06.789898  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000026 (ops 122-126)
I20260812 06:18:06.816998  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: LogGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:06.817574  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:06.841328  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.024s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.841914  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6): 447 bytes on disk
I20260812 06:18:06.842535  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.843155  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:06.859175  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.859745  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:07.139709  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.280s	user 0.181s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2124,"lbm_read_time_us":17986,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46029,"lbm_writes_lt_1ms":743,"mutex_wait_us":1644,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":34304,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:18:07.140813  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=18.063937
I20260812 06:18:07.217221  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.076s	user 0.044s	sys 0.025s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31602,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:07.217808  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:07.230378  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.230907  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:07.455960  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.225s	user 0.138s	sys 0.075s 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":327,"lbm_read_time_us":17366,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36345,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":3000}
I20260812 06:18:07.456744  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=18.063937
I20260812 06:18:07.529076  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.072s	user 0.043s	sys 0.012s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":26594,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:07.529636  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:07.541551  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s 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:18:07.542205  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:07.754696  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.212s	user 0.144s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1514,"lbm_read_time_us":17144,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35517,"lbm_writes_lt_1ms":643,"mutex_wait_us":405,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":3000}
I20260812 06:18:07.755580  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:07.806885  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.051s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23819,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.807592  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:07.821795  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.822333  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:08.004190  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.182s	user 0.122s	sys 0.060s 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":249,"lbm_read_time_us":14974,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31266,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:08.004902  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:08.071321  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.066s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.071926  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:08.084008  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.084558  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:08.279922  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.195s	user 0.137s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":14273,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31961,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:18:08.280682  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=14.095187
I20260812 06:18:08.346622  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.066s	user 0.015s	sys 0.039s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20496,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:08.347256  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:08.358459  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.359256  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushMRSOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:08.405478  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushMRSOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.046s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":2090,"drs_written":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2606,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:08.406272  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling LogGCOp(040452a29e1748c1870998276a74d2b6): free 120553628 bytes of WAL
I20260812 06:18:08.406555  1089 log_reader.cc:385] T 040452a29e1748c1870998276a74d2b6: removed 12 log segments from log reader
I20260812 06:18:08.406617  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000027 (ops 127-131)
I20260812 06:18:08.406656  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000028 (ops 132-136)
I20260812 06:18:08.406692  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000029 (ops 137-141)
I20260812 06:18:08.406724  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000030 (ops 142-146)
I20260812 06:18:08.406749  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000031 (ops 147-151)
I20260812 06:18:08.406770  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000032 (ops 152-156)
I20260812 06:18:08.406792  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000033 (ops 157-160)
I20260812 06:18:08.406824  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000034 (ops 161-165)
I20260812 06:18:08.406852  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000035 (ops 166-170)
I20260812 06:18:08.406874  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000036 (ops 171-175)
I20260812 06:18:08.406895  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000037 (ops 176-180)
I20260812 06:18:08.406917  1089 log.cc:1079] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: Deleting log segment in path: /tmp/dist-test-taskrgU4gR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515477244712-751-0/minicluster-data/ts-0-root/wals/040452a29e1748c1870998276a74d2b6/wal-000000038 (ops 181-184)
I20260812 06:18:08.443408  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: LogGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.037s	user 0.001s	sys 0.036s Metrics: {}
I20260812 06:18:08.444012  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=3.181125
I20260812 06:18:08.472012  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.028s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:08.472607  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:08.483639  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.484182  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6): 463 bytes on disk
I20260812 06:18:08.484874  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: UndoDeltaBlockGCOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.486014  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:08.728986  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.243s	user 0.142s	sys 0.097s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":184,"lbm_read_time_us":19381,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40148,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:08.729740  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=18.063937
I20260812 06:18:08.780678   751 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.404s	user 1.961s	sys 0.204s
I20260812 06:18:08.791641  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.062s	user 0.033s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29854,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:08.792112  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6): perf score=2.188937
I20260812 06:18:08.802287  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: FlushDeltaMemStoresOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.802798  1171 maintenance_manager.cc:419] P 31b1327de12340cc9b53f287795a6eb5: Scheduling MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6): perf score=1.000000
I20260812 06:18:08.812536   751 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.001s	sys 0.000s
I20260812 06:18:08.813071   751 tablet_server.cc:179] TabletServer@127.0.187.193:0 shutting down...
I20260812 06:18:08.960445  1089 maintenance_manager.cc:643] P 31b1327de12340cc9b53f287795a6eb5: MajorDeltaCompactionOp(040452a29e1748c1870998276a74d2b6) complete. Timing: real 0.157s	user 0.105s	sys 0.051s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":572,"lbm_read_time_us":11581,"lbm_reads_lt_1ms":618,"lbm_write_time_us":29538,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:18:08.961475   751 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:08.961750   751 tablet_replica.cc:333] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5: stopping tablet replica
I20260812 06:18:08.961925   751 raft_consensus.cc:2243] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.962121   751 raft_consensus.cc:2272] T 040452a29e1748c1870998276a74d2b6 P 31b1327de12340cc9b53f287795a6eb5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.977962   751 tablet_server.cc:196] TabletServer@127.0.187.193:0 shutdown complete.
I20260812 06:18:09.014619   751 master.cc:562] Master@127.0.187.254:44689 shutting down...
I20260812 06:18:09.018910   751 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:09.019186   751 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:09.019282   751 tablet_replica.cc:333] T 00000000000000000000000000000000 P b5d4d6580331417e933181bb81793f64: stopping tablet replica
I20260812 06:18:09.032215   751 master.cc:584] Master@127.0.187.254:44689 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6015 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11883 ms total)

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