[==========] 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:19:02.364935 25856 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.64.62:41927
I20260812 06:19:02.365993 25856 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:19:02.366639 25856 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.373196 25862 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.373198 25861 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.373528 25864 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.373564 25856 server_base.cc:1061] running on GCE node
I20260812 06:19:02.374112 25856 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.374233 25856 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.374282 25856 hybrid_clock.cc:648] HybridClock initialized: now 1786515542374279 us; error 0 us; skew 500 ppm
I20260812 06:19:02.376084 25856 webserver.cc:533] Webserver started at http://127.25.64.62:35289/ using document root <none> and password file <none>
I20260812 06:19:02.376639 25856 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.376727 25856 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.377002 25856 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.378633 25856 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/master-0-root/instance:
uuid: "a116aa53178940e0808ae3f2621a5985"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-qg60"
I20260812 06:19:02.382184 25856 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:02.384205 25869 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.385272 25856 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:02.385406 25856 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/master-0-root
uuid: "a116aa53178940e0808ae3f2621a5985"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-qg60"
I20260812 06:19:02.385509 25856 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.416092 25856 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.417071 25856 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:02.417268 25856 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.428257 25856 rpc_server.cc:307] RPC server started. Bound to: 127.25.64.62:41927
I20260812 06:19:02.428300 25931 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.64.62:41927 every 8 connection(s)
I20260812 06:19:02.432214 25932 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.439545 25932 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: Bootstrap starting.
I20260812 06:19:02.441988 25932 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.443198 25932 log.cc:826] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:02.445492 25932 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: No bootstrap required, opened a new log
I20260812 06:19:02.448414 25932 raft_consensus.cc:359] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER }
I20260812 06:19:02.448652 25932 raft_consensus.cc:385] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.448748 25932 raft_consensus.cc:740] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a116aa53178940e0808ae3f2621a5985, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.449443 25932 consensus_queue.cc:260] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [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: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER }
I20260812 06:19:02.449636 25932 raft_consensus.cc:399] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.449728 25932 raft_consensus.cc:493] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.449862 25932 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.450686 25932 raft_consensus.cc:515] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER }
I20260812 06:19:02.451226 25932 leader_election.cc:304] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [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: a116aa53178940e0808ae3f2621a5985; no voters: 
I20260812 06:19:02.451630 25932 leader_election.cc:290] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.451781 25936 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.452061 25936 raft_consensus.cc:697] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 1 LEADER]: Becoming Leader. State: Replica: a116aa53178940e0808ae3f2621a5985, State: Running, Role: LEADER
I20260812 06:19:02.452565 25936 consensus_queue.cc:237] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [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: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER }
I20260812 06:19:02.452768 25932 sys_catalog.cc:565] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.454988 25938 sys_catalog.cc:455] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a116aa53178940e0808ae3f2621a5985. Latest consensus state: current_term: 1 leader_uuid: "a116aa53178940e0808ae3f2621a5985" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER } }
I20260812 06:19:02.455102 25938 sys_catalog.cc:458] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.455262 25856 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.455339 25937 sys_catalog.cc:455] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a116aa53178940e0808ae3f2621a5985" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a116aa53178940e0808ae3f2621a5985" member_type: VOTER } }
I20260812 06:19:02.455454 25937 sys_catalog.cc:458] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:02.457417 25952 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:02.457489 25952 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:02.457571 25953 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.458505 25953 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.463399 25953 catalog_manager.cc:1383] Generated new cluster ID: db5857002a9f43dba24f6c19081938c2
I20260812 06:19:02.463487 25953 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.473137 25953 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.474025 25953 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.483163 25953 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: Generated new TSK 0
I20260812 06:19:02.483953 25953 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.487728 25856 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.490370 25957 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.490398 25960 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.490473 25958 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.490986 25856 server_base.cc:1061] running on GCE node
I20260812 06:19:02.491164 25856 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.491214 25856 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.491237 25856 hybrid_clock.cc:648] HybridClock initialized: now 1786515542491237 us; error 0 us; skew 500 ppm
I20260812 06:19:02.493047 25856 webserver.cc:533] Webserver started at http://127.25.64.1:44803/ using document root <none> and password file <none>
I20260812 06:19:02.493218 25856 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.493279 25856 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.493356 25856 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.493796 25856 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/instance:
uuid: "926c57eb67b0461486326777b688d504"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-qg60"
I20260812 06:19:02.495633 25856 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.496773 25965 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.497104 25856 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:02.497171 25856 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root
uuid: "926c57eb67b0461486326777b688d504"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-qg60"
I20260812 06:19:02.497265 25856 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.511278 25856 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.511791 25856 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.512329 25856 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.513229 25856 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.513281 25856 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.513347 25856 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.513386 25856 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.520249 25856 rpc_server.cc:307] RPC server started. Bound to: 127.25.64.1:40311
I20260812 06:19:02.520279 26036 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.64.1:40311 every 8 connection(s)
I20260812 06:19:02.530485 26037 heartbeater.cc:344] Connected to a master server at 127.25.64.62:41927
I20260812 06:19:02.530761 26037 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.531288 26037 heartbeater.cc:507] Master 127.25.64.62:41927 requested a full tablet report, sending...
I20260812 06:19:02.533773 25856 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012847677s
I20260812 06:19:02.533874 25888 ts_manager.cc:194] Registered new tserver with Master: 926c57eb67b0461486326777b688d504 (127.25.64.1:40311)
I20260812 06:19:02.535637 25888 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47098
I20260812 06:19:02.544333 25888 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47104:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:02.559713 25994 tablet_service.cc:1511] Processing CreateTablet for tablet d9fe0712a2324a69943dc0dd97e11c9b (DEFAULT_TABLE table=heavy-update-compaction-test [id=d919bfd701214437b7caede1625c548a]), partition=
I20260812 06:19:02.560216 25994 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d9fe0712a2324a69943dc0dd97e11c9b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.563205 26053 tablet_bootstrap.cc:492] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Bootstrap starting.
I20260812 06:19:02.564145 26053 tablet_bootstrap.cc:654] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.565375 26053 tablet_bootstrap.cc:492] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: No bootstrap required, opened a new log
I20260812 06:19:02.565531 26053 ts_tablet_manager.cc:1403] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.566090 26053 raft_consensus.cc:359] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "926c57eb67b0461486326777b688d504" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 40311 } }
I20260812 06:19:02.566228 26053 raft_consensus.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.566277 26053 raft_consensus.cc:740] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 926c57eb67b0461486326777b688d504, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.566421 26053 consensus_queue.cc:260] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [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: "926c57eb67b0461486326777b688d504" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 40311 } }
I20260812 06:19:02.566529 26053 raft_consensus.cc:399] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.566586 26053 raft_consensus.cc:493] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.566644 26053 raft_consensus.cc:3060] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.567788 26053 raft_consensus.cc:515] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "926c57eb67b0461486326777b688d504" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 40311 } }
I20260812 06:19:02.567958 26053 leader_election.cc:304] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [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: 926c57eb67b0461486326777b688d504; no voters: 
I20260812 06:19:02.568219 26053 leader_election.cc:290] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.568322 26056 raft_consensus.cc:2804] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.568539 26056 raft_consensus.cc:697] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 1 LEADER]: Becoming Leader. State: Replica: 926c57eb67b0461486326777b688d504, State: Running, Role: LEADER
I20260812 06:19:02.568629 26053 ts_tablet_manager.cc:1434] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:02.568789 26056 consensus_queue.cc:237] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [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: "926c57eb67b0461486326777b688d504" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 40311 } }
I20260812 06:19:02.569013 26037 heartbeater.cc:499] Master 127.25.64.62:41927 was elected leader, sending a full tablet report...
I20260812 06:19:02.571614 25886 catalog_manager.cc:5719] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 reported cstate change: term changed from 0 to 1, leader changed from <none> to 926c57eb67b0461486326777b688d504 (127.25.64.1). New cstate: current_term: 1 leader_uuid: "926c57eb67b0461486326777b688d504" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "926c57eb67b0461486326777b688d504" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 40311 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.643494 25856 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.020s	sys 0.008s
I20260812 06:19:02.771430 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=15.086190
I20260812 06:19:02.937943 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.166s	user 0.133s	sys 0.028s Metrics: {"bytes_written":12717736,"cfile_init":1,"compiler_manager_pool.queue_time_us":189,"delete_count":0,"dirs.queue_time_us":1124,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1858,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41343,"lbm_writes_lt_1ms":667,"mutex_wait_us":1846,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":405760,"thread_start_us":120,"threads_started":1,"update_count":1550}
I20260812 06:19:02.939042 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 11976772 bytes of WAL
I20260812 06:19:02.939487 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 1 log segments from log reader
I20260812 06:19:02.939567 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000001 (ops 1-6)
I20260812 06:19:02.942888 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {"spinlock_wait_cycles":162688}
I20260812 06:19:02.943293 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b): 12308959 bytes on disk
I20260812 06:19:02.944041 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.944484 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:02.963461 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.963924 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:02.974095 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.974565 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:03.146128 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.171s	user 0.151s	sys 0.019s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":823,"lbm_read_time_us":10758,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33800,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":347,"threads_started":5,"update_count":2500}
I20260812 06:19:03.146682 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:03.192289 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.045s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17597,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.192866 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:03.204424 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.205111 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:03.339246 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.134s	user 0.103s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":9000,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28525,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:03.339819 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:03.388469 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.048s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20569,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.389026 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:03.404606 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.405257 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:03.534992 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":8995,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26348,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:03.535514 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:03.588542 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.053s	user 0.031s	sys 0.014s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.589187 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:03.600311 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.600867 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:03.756536 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.155s	user 0.125s	sys 0.029s 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":632,"lbm_read_time_us":11750,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25360,"lbm_writes_lt_1ms":443,"mutex_wait_us":390,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:03.760839 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:03.807202 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.046s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14600,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.807686 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:03.819373 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.819953 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:03.950657 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.131s	user 0.092s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":653,"lbm_read_time_us":10242,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25314,"lbm_writes_lt_1ms":443,"mutex_wait_us":98,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:03.951351 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:03.998029 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.047s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18234,"lbm_writes_lt_1ms":303,"mutex_wait_us":1,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.998559 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.009949 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.010618 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:04.139647 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.129s	user 0.096s	sys 0.032s 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":1072,"lbm_read_time_us":9963,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24058,"lbm_writes_lt_1ms":443,"mutex_wait_us":320,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:04.140359 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:04.178388 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.038s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.178890 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.194842 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.195370 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:04.225471 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1946,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1633,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:04.226361 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 121006369 bytes of WAL
I20260812 06:19:04.226650 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 12 log segments from log reader
I20260812 06:19:04.226712 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000002 (ops 7-11)
I20260812 06:19:04.226753 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000003 (ops 12-16)
I20260812 06:19:04.226790 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000004 (ops 17-21)
I20260812 06:19:04.226816 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000005 (ops 22-26)
I20260812 06:19:04.226845 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000006 (ops 27-31)
I20260812 06:19:04.226874 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000007 (ops 32-36)
I20260812 06:19:04.226903 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000008 (ops 37-41)
I20260812 06:19:04.226935 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000009 (ops 42-46)
I20260812 06:19:04.226965 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000010 (ops 47-50)
I20260812 06:19:04.226991 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000011 (ops 51-55)
I20260812 06:19:04.227020 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000012 (ops 56-60)
I20260812 06:19:04.227051 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000013 (ops 61-65)
I20260812 06:19:04.257994 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:04.258455 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.279304 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.279796 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b): 462 bytes on disk
I20260812 06:19:04.280205 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.280647 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.291752 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.292464 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:04.476851 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.184s	user 0.152s	sys 0.020s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":669,"lbm_read_time_us":13858,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35070,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:19:04.477434 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=14.095187
I20260812 06:19:04.531832 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.054s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22818,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.532311 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.544087 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.544536 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:04.708354 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.164s	user 0.152s	sys 0.012s 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":656,"lbm_read_time_us":12199,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32939,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:19:04.709153 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:04.742646 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.033s	user 0.008s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.743131 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.759826 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6401,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.760413 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:04.906142 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.146s	user 0.103s	sys 0.038s 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":291,"lbm_read_time_us":9478,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24389,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2000}
I20260812 06:19:04.906723 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=11.118625
I20260812 06:19:04.937217 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.030s	user 0.021s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13535,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.937752 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:04.954825 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5486,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.955288 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:05.103389 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.148s	user 0.099s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":7997,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25486,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:19:05.104393 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=10.126437
I20260812 06:19:05.140362 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14924,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.141160 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:05.169447 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.028s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.169996 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:05.180702 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s 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:19:05.181217 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:05.345010 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.164s	user 0.114s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":364,"lbm_read_time_us":10532,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30941,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:05.345688 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=14.095187
I20260812 06:19:05.400065 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.054s	user 0.020s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24137,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:05.400631 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:05.411280 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.411803 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:05.572456 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.160s	user 0.129s	sys 0.028s 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":279,"lbm_read_time_us":11112,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31020,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:19:05.573211 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=11.118625
I20260812 06:19:05.626152 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.053s	user 0.028s	sys 0.023s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":23379,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:05.626724 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:05.650972 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.024s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5906,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.651482 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:05.667088 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.667822 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:05.701835 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.034s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1557,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1794,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:05.702756 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 120553433 bytes of WAL
I20260812 06:19:05.703125 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 12 log segments from log reader
I20260812 06:19:05.703207 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000014 (ops 66-70)
I20260812 06:19:05.703258 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000015 (ops 71-75)
I20260812 06:19:05.703317 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000016 (ops 76-80)
I20260812 06:19:05.703359 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000017 (ops 81-85)
I20260812 06:19:05.703400 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000018 (ops 86-90)
I20260812 06:19:05.703438 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000019 (ops 91-94)
I20260812 06:19:05.703480 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000020 (ops 95-99)
I20260812 06:19:05.703518 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000021 (ops 100-104)
I20260812 06:19:05.703559 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000022 (ops 105-109)
I20260812 06:19:05.703599 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000023 (ops 110-114)
I20260812 06:19:05.703639 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000024 (ops 115-118)
I20260812 06:19:05.703678 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000025 (ops 119-123)
I20260812 06:19:05.730132 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:05.730774 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=4.173312
I20260812 06:19:05.745368 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":5415441,"delete_count":0,"lbm_write_time_us":5824,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:19:05.745843 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 12017932 bytes of WAL
I20260812 06:19:05.746068 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 1 log segments from log reader
I20260812 06:19:05.746114 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000026 (ops 124-128)
I20260812 06:19:05.748414 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:05.748806 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b): 472 bytes on disk
I20260812 06:19:05.749238 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.749749 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.196750
I20260812 06:19:05.767390 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.017s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:05.767983 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:05.965732 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.198s	user 0.146s	sys 0.051s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938867,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":235,"lbm_read_time_us":12927,"lbm_reads_lt_1ms":767,"lbm_write_time_us":45142,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:19:05.968128 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=14.095187
I20260812 06:19:06.014853 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.046s	user 0.012s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21461,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.015594 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.047508 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.032s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.048017 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.060707 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.061489 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:06.249434 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.188s	user 0.134s	sys 0.053s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836253,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":845,"lbm_read_time_us":14611,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39963,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:19:06.249993 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=14.095187
I20260812 06:19:06.315526 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.065s	user 0.023s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28672,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.316355 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.342715 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.026s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.343218 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.353960 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.354562 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:06.527694 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.173s	user 0.147s	sys 0.025s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836253,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":738,"lbm_read_time_us":13966,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36476,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1220352,"update_count":3000}
I20260812 06:19:06.528367 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=14.095187
I20260812 06:19:06.577497 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.049s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21298,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.578198 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.589371 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.589816 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:06.748699 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.159s	user 0.108s	sys 0.039s 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":500,"lbm_read_time_us":10586,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30623,"lbm_writes_lt_1ms":543,"mutex_wait_us":175,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:06.749419 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=11.118625
I20260812 06:19:06.818657 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.069s	user 0.025s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":47112,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.819219 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.829871 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.830371 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:06.840164 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.010s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.840662 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:07.025207 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.184s	user 0.135s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":182,"lbm_read_time_us":12684,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32476,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2500}
I20260812 06:19:07.025945 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=12.110812
I20260812 06:19:07.075805 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.050s	user 0.012s	sys 0.035s Metrics: {"bytes_written":14276639,"delete_count":0,"lbm_write_time_us":23499,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":349,"reinsert_count":0,"update_count":1740}
I20260812 06:19:07.076376 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.196750
I20260812 06:19:07.092154 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2543708,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:19:07.092680 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:07.103366 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.103813 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:07.139227 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushMRSOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.035s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":339,"dirs.run_wall_time_us":1602,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2060,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:07.139906 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 108535637 bytes of WAL
I20260812 06:19:07.140147 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 11 log segments from log reader
I20260812 06:19:07.140216 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000027 (ops 129-133)
I20260812 06:19:07.140271 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000028 (ops 134-138)
I20260812 06:19:07.140333 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000029 (ops 139-143)
I20260812 06:19:07.140377 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000030 (ops 144-148)
I20260812 06:19:07.140414 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000031 (ops 149-153)
I20260812 06:19:07.140452 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000032 (ops 154-158)
I20260812 06:19:07.140491 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000033 (ops 159-162)
I20260812 06:19:07.140530 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000034 (ops 163-167)
I20260812 06:19:07.140569 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000035 (ops 168-172)
I20260812 06:19:07.140607 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000036 (ops 173-176)
I20260812 06:19:07.140646 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000037 (ops 177-181)
I20260812 06:19:07.162353 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:07.162873 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b): 463 bytes on disk
I20260812 06:19:07.163424 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: UndoDeltaBlockGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.164054 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:07.183189 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.019s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.183641 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b): free 12018014 bytes of WAL
I20260812 06:19:07.183854 25970 log_reader.cc:385] T d9fe0712a2324a69943dc0dd97e11c9b: removed 1 log segments from log reader
I20260812 06:19:07.183919 25970 log.cc:1079] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/d9fe0712a2324a69943dc0dd97e11c9b/wal-000000038 (ops 182-186)
I20260812 06:19:07.186336 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: LogGCOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:07.186642 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:07.197974 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.198684 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:07.425037 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.226s	user 0.150s	sys 0.063s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":3234,"lbm_read_time_us":15258,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39885,"lbm_writes_lt_1ms":743,"mutex_wait_us":1,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:19:07.425694 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=18.063937
I20260812 06:19:07.483086 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.057s	user 0.038s	sys 0.016s Metrics: {"bytes_written":20512313,"delete_count":0,"lbm_write_time_us":26090,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:07.483632 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=2.188937
I20260812 06:19:07.494577 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: FlushDeltaMemStoresOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.495182 26038 maintenance_manager.cc:419] P 926c57eb67b0461486326777b688d504: Scheduling MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b): perf score=1.000000
I20260812 06:19:07.529605 25856 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.886s	user 1.892s	sys 0.079s
I20260812 06:19:07.586825 25856 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.002s	sys 0.000s
I20260812 06:19:07.587570 25856 tablet_server.cc:179] TabletServer@127.25.64.1:0 shutting down...
I20260812 06:19:07.659667 25970 maintenance_manager.cc:643] P 926c57eb67b0461486326777b688d504: MajorDeltaCompactionOp(d9fe0712a2324a69943dc0dd97e11c9b) complete. Timing: real 0.164s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836135,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":13545,"lbm_reads_lt_1ms":668,"lbm_write_time_us":33402,"lbm_writes_lt_1ms":643,"mutex_wait_us":115,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:19:07.660478 25856 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.660959 25856 tablet_replica.cc:333] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504: stopping tablet replica
I20260812 06:19:07.661230 25856 raft_consensus.cc:2243] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.661520 25856 raft_consensus.cc:2272] T d9fe0712a2324a69943dc0dd97e11c9b P 926c57eb67b0461486326777b688d504 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.678332 25856 tablet_server.cc:196] TabletServer@127.25.64.1:0 shutdown complete.
I20260812 06:19:07.713578 25856 master.cc:562] Master@127.25.64.62:41927 shutting down...
I20260812 06:19:07.718052 25856 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.718256 25856 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.718356 25856 tablet_replica.cc:333] T 00000000000000000000000000000000 P a116aa53178940e0808ae3f2621a5985: stopping tablet replica
I20260812 06:19:07.730809 25856 master.cc:584] Master@127.25.64.62:41927 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5456 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:07.821061 25856 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.64.62:33279
I20260812 06:19:07.821583 25856 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.823841 26074 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.823841 26073 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.823951 25856 server_base.cc:1061] running on GCE node
W20260812 06:19:07.823976 26076 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.824361 25856 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.824406 25856 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.824422 25856 hybrid_clock.cc:648] HybridClock initialized: now 1786515547824422 us; error 0 us; skew 500 ppm
I20260812 06:19:07.825482 25856 webserver.cc:533] Webserver started at http://127.25.64.62:32935/ using document root <none> and password file <none>
I20260812 06:19:07.825664 25856 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.825738 25856 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.825848 25856 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.826251 25856 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/master-0-root/instance:
uuid: "e41dd3e37ba74fd48666b03c721dbbc5"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-qg60"
I20260812 06:19:07.827840 25856 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:07.828979 26081 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.829276 25856 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:07.829365 25856 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/master-0-root
uuid: "e41dd3e37ba74fd48666b03c721dbbc5"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-qg60"
I20260812 06:19:07.829447 25856 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.837060 25856 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.837473 25856 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.842316 25856 rpc_server.cc:307] RPC server started. Bound to: 127.25.64.62:33279
I20260812 06:19:07.846057 26137 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.64.62:33279 every 8 connection(s)
I20260812 06:19:07.848690 26138 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.855546 26138 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5: Bootstrap starting.
I20260812 06:19:07.856364 26138 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.857496 26138 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5: No bootstrap required, opened a new log
I20260812 06:19:07.857872 26138 raft_consensus.cc:359] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER }
I20260812 06:19:07.857959 26138 raft_consensus.cc:385] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.857981 26138 raft_consensus.cc:740] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e41dd3e37ba74fd48666b03c721dbbc5, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.858151 26138 consensus_queue.cc:260] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [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: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER }
I20260812 06:19:07.858248 26138 raft_consensus.cc:399] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.858275 26138 raft_consensus.cc:493] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.858306 26138 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.858981 26138 raft_consensus.cc:515] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER }
I20260812 06:19:07.859097 26138 leader_election.cc:304] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [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: e41dd3e37ba74fd48666b03c721dbbc5; no voters: 
I20260812 06:19:07.859268 26138 leader_election.cc:290] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.859429 26142 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.859668 26142 raft_consensus.cc:697] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 1 LEADER]: Becoming Leader. State: Replica: e41dd3e37ba74fd48666b03c721dbbc5, State: Running, Role: LEADER
I20260812 06:19:07.859810 26138 sys_catalog.cc:565] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:07.859853 26142 consensus_queue.cc:237] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [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: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER }
I20260812 06:19:07.860355 26143 sys_catalog.cc:455] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER } }
I20260812 06:19:07.860416 26144 sys_catalog.cc:455] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e41dd3e37ba74fd48666b03c721dbbc5. Latest consensus state: current_term: 1 leader_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e41dd3e37ba74fd48666b03c721dbbc5" member_type: VOTER } }
I20260812 06:19:07.860519 26143 sys_catalog.cc:458] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.860615 26144 sys_catalog.cc:458] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.861311 26150 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:07.862139 26150 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:07.862344 25856 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:07.864266 26150 catalog_manager.cc:1383] Generated new cluster ID: 2de66187f5f64939a9fa3ac0e92958cb
I20260812 06:19:07.864337 26150 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:07.874298 26150 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:07.874949 26150 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:07.879420 26150 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5: Generated new TSK 0
I20260812 06:19:07.879634 26150 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:07.894815 25856 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.897001 26161 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.897034 26162 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.897141 26165 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.897272 25856 server_base.cc:1061] running on GCE node
I20260812 06:19:07.897588 25856 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.897643 25856 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.897660 25856 hybrid_clock.cc:648] HybridClock initialized: now 1786515547897660 us; error 0 us; skew 500 ppm
I20260812 06:19:07.898695 25856 webserver.cc:533] Webserver started at http://127.25.64.1:42853/ using document root <none> and password file <none>
I20260812 06:19:07.898880 25856 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.898931 25856 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.899010 25856 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.899435 25856 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/instance:
uuid: "2a14d66f1d3644c49a262e122b08e65c"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-qg60"
I20260812 06:19:07.901172 25856 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:07.902267 26171 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.902621 25856 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:07.902706 25856 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root
uuid: "2a14d66f1d3644c49a262e122b08e65c"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-qg60"
I20260812 06:19:07.902778 25856 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.907634 25856 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.907917 25856 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.908161 25856 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:07.908628 25856 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:07.908665 25856 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.908725 25856 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:07.908799 25856 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.913573 25856 rpc_server.cc:307] RPC server started. Bound to: 127.25.64.1:41301
I20260812 06:19:07.914664 26241 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.64.1:41301 every 8 connection(s)
I20260812 06:19:07.925907 26242 heartbeater.cc:344] Connected to a master server at 127.25.64.62:33279
I20260812 06:19:07.926059 26242 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:07.926337 26242 heartbeater.cc:507] Master 127.25.64.62:33279 requested a full tablet report, sending...
I20260812 06:19:07.927039 26100 ts_manager.cc:194] Registered new tserver with Master: 2a14d66f1d3644c49a262e122b08e65c (127.25.64.1:41301)
I20260812 06:19:07.927789 25856 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013211541s
I20260812 06:19:07.927872 26100 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55110
I20260812 06:19:07.935511 26100 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55126:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:07.945026 26204 tablet_service.cc:1511] Processing CreateTablet for tablet 90a650b097f94a40a3c42e540cb61b35 (DEFAULT_TABLE table=heavy-update-compaction-test [id=161129107afe4b59a179d07d59904b71]), partition=
I20260812 06:19:07.945366 26204 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 90a650b097f94a40a3c42e540cb61b35. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.947778 26255 tablet_bootstrap.cc:492] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Bootstrap starting.
I20260812 06:19:07.948674 26255 tablet_bootstrap.cc:654] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.949963 26255 tablet_bootstrap.cc:492] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: No bootstrap required, opened a new log
I20260812 06:19:07.950062 26255 ts_tablet_manager.cc:1403] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:07.950626 26255 raft_consensus.cc:359] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a14d66f1d3644c49a262e122b08e65c" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 41301 } }
I20260812 06:19:07.950716 26255 raft_consensus.cc:385] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.950738 26255 raft_consensus.cc:740] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2a14d66f1d3644c49a262e122b08e65c, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.950901 26255 consensus_queue.cc:260] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [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: "2a14d66f1d3644c49a262e122b08e65c" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 41301 } }
I20260812 06:19:07.950974 26255 raft_consensus.cc:399] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.950999 26255 raft_consensus.cc:493] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.951081 26255 raft_consensus.cc:3060] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.951812 26255 raft_consensus.cc:515] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a14d66f1d3644c49a262e122b08e65c" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 41301 } }
I20260812 06:19:07.951987 26255 leader_election.cc:304] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [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: 2a14d66f1d3644c49a262e122b08e65c; no voters: 
I20260812 06:19:07.952224 26255 leader_election.cc:290] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.952375 26257 raft_consensus.cc:2804] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.952540 26255 ts_tablet_manager.cc:1434] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:07.952559 26242 heartbeater.cc:499] Master 127.25.64.62:33279 was elected leader, sending a full tablet report...
I20260812 06:19:07.952687 26257 raft_consensus.cc:697] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 1 LEADER]: Becoming Leader. State: Replica: 2a14d66f1d3644c49a262e122b08e65c, State: Running, Role: LEADER
I20260812 06:19:07.952872 26257 consensus_queue.cc:237] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [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: "2a14d66f1d3644c49a262e122b08e65c" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 41301 } }
I20260812 06:19:07.954301 26100 catalog_manager.cc:5719] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c reported cstate change: term changed from 0 to 1, leader changed from <none> to 2a14d66f1d3644c49a262e122b08e65c (127.25.64.1). New cstate: current_term: 1 leader_uuid: "2a14d66f1d3644c49a262e122b08e65c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2a14d66f1d3644c49a262e122b08e65c" member_type: VOTER last_known_addr { host: "127.25.64.1" port: 41301 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:08.018968 25856 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.016s	sys 0.008s
I20260812 06:19:08.165485 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushMRSOp(90a650b097f94a40a3c42e540cb61b35): perf score=19.054940
I20260812 06:19:08.325539 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushMRSOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.160s	user 0.103s	sys 0.056s Metrics: {"bytes_written":9599900,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1092,"drs_written":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38504,"lbm_writes_lt_1ms":691,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":9856,"update_count":1170}
I20260812 06:19:08.326527 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling LogGCOp(90a650b097f94a40a3c42e540cb61b35): free 20743880 bytes of WAL
I20260812 06:19:08.326752 26178 log_reader.cc:385] T 90a650b097f94a40a3c42e540cb61b35: removed 2 log segments from log reader
I20260812 06:19:08.326828 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000001 (ops 1-6)
I20260812 06:19:08.326905 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000002 (ops 7-11)
I20260812 06:19:08.332099 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: LogGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:08.332456 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35): 16411393 bytes on disk
I20260812 06:19:08.333148 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.333565 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.196750
I20260812 06:19:08.351399 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4326,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:19:08.352062 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:08.481300 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.129s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569833,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":661,"lbm_read_time_us":9047,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22877,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":364,"threads_started":5,"update_count":1500}
I20260812 06:19:08.481995 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=10.126437
I20260812 06:19:08.523856 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17621,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.524354 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=3.181125
I20260812 06:19:08.556706 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.032s	user 0.010s	sys 0.013s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5900,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:08.557376 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:08.567854 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.568347 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:08.760591 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.192s	user 0.116s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":628,"lbm_read_time_us":15293,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31055,"lbm_writes_lt_1ms":543,"mutex_wait_us":263,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:19:08.761209 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=11.118625
I20260812 06:19:08.808604 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.047s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22678,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.809352 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:08.827521 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.828014 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:08.847498 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3891,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.848078 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.035917 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.188s	user 0.116s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":248,"lbm_read_time_us":12839,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31694,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:19:09.036653 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=11.118625
I20260812 06:19:09.081120 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.044s	user 0.035s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19192,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.081790 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:09.098892 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.017s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5631,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.099494 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.241881 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.142s	user 0.131s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":80,"lbm_read_time_us":9653,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29635,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:19:09.242677 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=10.126437
I20260812 06:19:09.283962 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.041s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18012,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.284416 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:09.294997 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.295842 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.422061 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.126s	user 0.090s	sys 0.035s 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":486,"lbm_read_time_us":8597,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24084,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:19:09.422587 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=10.126437
I20260812 06:19:09.462153 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.039s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15867,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.462776 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:09.474181 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.475011 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.615849 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.141s	user 0.099s	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":235,"lbm_read_time_us":10731,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27423,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:09.616448 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=10.126437
I20260812 06:19:09.672324 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.056s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18546,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.673091 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:09.689774 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.690294 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushMRSOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.720636 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushMRSOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1426,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1386,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:09.721374 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:09.901551 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.180s	user 0.093s	sys 0.076s 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":281,"lbm_read_time_us":11887,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29448,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:09.902388 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling LogGCOp(90a650b097f94a40a3c42e540cb61b35): free 120553334 bytes of WAL
I20260812 06:19:09.902662 26178 log_reader.cc:385] T 90a650b097f94a40a3c42e540cb61b35: removed 12 log segments from log reader
I20260812 06:19:09.902714 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000003 (ops 12-16)
I20260812 06:19:09.902762 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000004 (ops 17-21)
I20260812 06:19:09.902849 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000005 (ops 22-26)
I20260812 06:19:09.902897 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000006 (ops 27-30)
I20260812 06:19:09.902935 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000007 (ops 31-35)
I20260812 06:19:09.902974 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000008 (ops 36-40)
I20260812 06:19:09.903019 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000009 (ops 41-45)
I20260812 06:19:09.903061 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000010 (ops 46-50)
I20260812 06:19:09.903103 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000011 (ops 51-55)
I20260812 06:19:09.903142 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000012 (ops 56-60)
I20260812 06:19:09.903184 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000013 (ops 61-64)
I20260812 06:19:09.903232 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000014 (ops 65-69)
I20260812 06:19:09.929142 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: LogGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:09.929615 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35): 462 bytes on disk
I20260812 06:19:09.930124 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.930841 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:09.977118 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.046s	user 0.031s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19755,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.977720 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=3.181125
I20260812 06:19:09.999904 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.022s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5247,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:10.000553 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:10.012405 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4575,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.012966 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:10.257357 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.244s	user 0.158s	sys 0.085s 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":952,"lbm_read_time_us":17402,"lbm_reads_lt_1ms":673,"lbm_write_time_us":43654,"lbm_writes_lt_1ms":643,"mutex_wait_us":105,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:19:10.258059 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:10.325512 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.067s	user 0.042s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24184,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.326071 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:10.342942 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.343428 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:10.531845 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.188s	user 0.130s	sys 0.057s 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":1229,"lbm_read_time_us":13186,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30759,"lbm_writes_lt_1ms":543,"mutex_wait_us":376,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:19:10.532838 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:10.584143 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.051s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23559,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.584779 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:10.606992 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.022s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.607538 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:10.798293 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.191s	user 0.126s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":848,"lbm_read_time_us":11286,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35620,"lbm_writes_lt_1ms":543,"mutex_wait_us":350,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:19:10.798991 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:10.845371 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21403,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.845893 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:10.859707 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.860386 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:11.046445 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.186s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":10179,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30109,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":2500}
I20260812 06:19:11.047057 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:11.097047 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.050s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22759,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.097503 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:11.109624 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.110165 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:11.265318 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.155s	user 0.113s	sys 0.033s 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":222,"lbm_read_time_us":9284,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31676,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:11.266152 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:11.324977 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.059s	user 0.043s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.325567 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:11.338486 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.339097 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushMRSOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:11.373729 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushMRSOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.034s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1693,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1767,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:11.374436 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling LogGCOp(90a650b097f94a40a3c42e540cb61b35): free 121006490 bytes of WAL
I20260812 06:19:11.374696 26178 log_reader.cc:385] T 90a650b097f94a40a3c42e540cb61b35: removed 12 log segments from log reader
I20260812 06:19:11.374763 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000015 (ops 70-74)
I20260812 06:19:11.374822 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000016 (ops 75-79)
I20260812 06:19:11.374887 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000017 (ops 80-84)
I20260812 06:19:11.374933 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000018 (ops 85-89)
I20260812 06:19:11.374974 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000019 (ops 90-94)
I20260812 06:19:11.375015 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000020 (ops 95-99)
I20260812 06:19:11.375058 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000021 (ops 100-104)
I20260812 06:19:11.375098 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000022 (ops 105-109)
I20260812 06:19:11.375139 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000023 (ops 110-114)
I20260812 06:19:11.375181 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000024 (ops 115-118)
I20260812 06:19:11.375221 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000025 (ops 119-123)
I20260812 06:19:11.375263 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000026 (ops 124-128)
I20260812 06:19:11.405711 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: LogGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:11.406206 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=3.181125
I20260812 06:19:11.424371 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.018s	user 0.002s	sys 0.014s Metrics: {"bytes_written":5169286,"delete_count":0,"lbm_write_time_us":7782,"lbm_writes_lt_1ms":129,"reinsert_count":0,"update_count":630}
I20260812 06:19:11.424937 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling LogGCOp(90a650b097f94a40a3c42e540cb61b35): free 11564891 bytes of WAL
I20260812 06:19:11.425158 26178 log_reader.cc:385] T 90a650b097f94a40a3c42e540cb61b35: removed 1 log segments from log reader
I20260812 06:19:11.425203 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000027 (ops 129-132)
I20260812 06:19:11.427379 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: LogGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:11.427701 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35): 483 bytes on disk
I20260812 06:19:11.428107 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:11.428579 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.196750
I20260812 06:19:11.438500 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":3567,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:19:11.438966 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:11.673786 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.235s	user 0.160s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":651,"lbm_read_time_us":17118,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39699,"lbm_writes_lt_1ms":743,"mutex_wait_us":48,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:19:11.674422 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=18.063937
I20260812 06:19:11.751464 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.077s	user 0.034s	sys 0.040s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":37759,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.752101 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:11.772025 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.019s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.772639 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:11.988466 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.216s	user 0.142s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1142,"lbm_read_time_us":15191,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33861,"lbm_writes_lt_1ms":643,"mutex_wait_us":322,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":3000}
I20260812 06:19:11.989111 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=18.063937
I20260812 06:19:12.057200 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.068s	user 0.047s	sys 0.016s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":30032,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:12.057758 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:12.068967 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.011s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.069581 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:12.275803 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.206s	user 0.132s	sys 0.071s 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":1184,"lbm_read_time_us":15233,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34241,"lbm_writes_lt_1ms":643,"mutex_wait_us":310,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":3000}
I20260812 06:19:12.276648 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=16.079562
I20260812 06:19:12.349200 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.072s	user 0.049s	sys 0.013s Metrics: {"bytes_written":17968825,"delete_count":0,"lbm_write_time_us":28559,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":440,"reinsert_count":0,"update_count":2190}
I20260812 06:19:12.349668 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=5.165500
I20260812 06:19:12.366827 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":6646162,"delete_count":0,"lbm_write_time_us":7009,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:19:12.367309 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:12.569689 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.202s	user 0.147s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":13734,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35707,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":3000}
I20260812 06:19:12.571568 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=15.087375
I20260812 06:19:12.622095 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.050s	user 0.013s	sys 0.035s Metrics: {"bytes_written":16656046,"delete_count":0,"lbm_write_time_us":22553,"lbm_writes_lt_1ms":409,"reinsert_count":0,"update_count":2030}
I20260812 06:19:12.622761 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:12.644007 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.021s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":5676,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:12.644693 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:12.823597 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.179s	user 0.140s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":660,"lbm_read_time_us":11797,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30800,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:19:12.824198 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=15.087375
I20260812 06:19:12.876941 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.053s	user 0.045s	sys 0.007s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24103,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:12.877774 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:12.891515 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4946,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.892112 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushMRSOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:12.921154 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushMRSOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1712,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1939,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1280}
I20260812 06:19:12.921914 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling LogGCOp(90a650b097f94a40a3c42e540cb61b35): free 121006714 bytes of WAL
I20260812 06:19:12.922207 26178 log_reader.cc:385] T 90a650b097f94a40a3c42e540cb61b35: removed 12 log segments from log reader
I20260812 06:19:12.922266 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000028 (ops 133-137)
I20260812 06:19:12.922302 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000029 (ops 138-142)
I20260812 06:19:12.922338 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000030 (ops 143-147)
I20260812 06:19:12.922381 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000031 (ops 148-152)
I20260812 06:19:12.922405 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000032 (ops 153-156)
I20260812 06:19:12.922432 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000033 (ops 157-161)
I20260812 06:19:12.922461 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000034 (ops 162-166)
I20260812 06:19:12.922495 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000035 (ops 167-171)
I20260812 06:19:12.922528 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000036 (ops 172-176)
I20260812 06:19:12.922556 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000037 (ops 177-181)
I20260812 06:19:12.922585 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000038 (ops 182-186)
I20260812 06:19:12.922613 26178 log.cc:1079] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: Deleting log segment in path: /tmp/dist-test-taskRScjy0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542353899-25856-0/minicluster-data/ts-0-root/wals/90a650b097f94a40a3c42e540cb61b35/wal-000000039 (ops 187-191)
I20260812 06:19:12.953429 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: LogGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:12.953878 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=3.181125
I20260812 06:19:12.973053 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":7261,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:12.973483 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=2.188937
I20260812 06:19:12.983255 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.010s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.983690 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:13.176937 25856 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.158s	user 1.917s	sys 0.166s
I20260812 06:19:13.199153 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.215s	user 0.154s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979725,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17876,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38568,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3500}
I20260812 06:19:13.199646 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35): 472 bytes on disk
I20260812 06:19:13.200044 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: UndoDeltaBlockGCOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:19:13.200563 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35): perf score=14.095187
I20260812 06:19:13.233768 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: FlushDeltaMemStoresOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16215,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:13.234227 26243 maintenance_manager.cc:419] P 2a14d66f1d3644c49a262e122b08e65c: Scheduling MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35): perf score=1.000000
I20260812 06:19:13.262727 25856 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.085s	user 0.001s	sys 0.000s
I20260812 06:19:13.263302 25856 tablet_server.cc:179] TabletServer@127.25.64.1:0 shutting down...
I20260812 06:19:13.348656 26178 maintenance_manager.cc:643] P 2a14d66f1d3644c49a262e122b08e65c: MajorDeltaCompactionOp(90a650b097f94a40a3c42e540cb61b35) complete. Timing: real 0.114s	user 0.076s	sys 0.034s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2674,"lbm_read_time_us":7521,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24209,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":2257,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.349596 25856 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:13.349960 25856 tablet_replica.cc:333] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c: stopping tablet replica
I20260812 06:19:13.350133 25856 raft_consensus.cc:2243] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:13.350306 25856 raft_consensus.cc:2272] T 90a650b097f94a40a3c42e540cb61b35 P 2a14d66f1d3644c49a262e122b08e65c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:13.364646 25856 tablet_server.cc:196] TabletServer@127.25.64.1:0 shutdown complete.
I20260812 06:19:13.384654 25856 master.cc:562] Master@127.25.64.62:33279 shutting down...
I20260812 06:19:13.388439 25856 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:13.388630 25856 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:13.388684 25856 tablet_replica.cc:333] T 00000000000000000000000000000000 P e41dd3e37ba74fd48666b03c721dbbc5: stopping tablet replica
I20260812 06:19:13.401405 25856 master.cc:584] Master@127.25.64.62:33279 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5668 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11126 ms total)

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