[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:26.453750  4379 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.70.254:38107
I20260812 06:18:26.454787  4379 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:26.455412  4379 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:26.462344  4391 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:26.462447  4388 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:26.462486  4379 server_base.cc:1061] running on GCE node
W20260812 06:18:26.462713  4387 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:26.463261  4379 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:26.463397  4379 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:26.463443  4379 hybrid_clock.cc:648] HybridClock initialized: now 1786515506463440 us; error 0 us; skew 500 ppm
I20260812 06:18:26.465401  4379 webserver.cc:533] Webserver started at http://127.4.70.254:34391/ using document root <none> and password file <none>
I20260812 06:18:26.465998  4379 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:26.466091  4379 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:26.466360  4379 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:26.468057  4379 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/master-0-root/instance:
uuid: "1dbe5f1d161e4d638a1fedb90dac3716"
format_stamp: "Formatted at 2026-08-12 06:18:26 on dist-test-slave-s11t"
I20260812 06:18:26.471679  4379 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:26.473935  4402 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:26.474972  4379 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:18:26.475122  4379 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/master-0-root
uuid: "1dbe5f1d161e4d638a1fedb90dac3716"
format_stamp: "Formatted at 2026-08-12 06:18:26 on dist-test-slave-s11t"
I20260812 06:18:26.475260  4379 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:26.510598  4379 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:26.511363  4379 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:26.511579  4379 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:26.520543  4379 rpc_server.cc:307] RPC server started. Bound to: 127.4.70.254:38107
I20260812 06:18:26.520574  4478 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.70.254:38107 every 8 connection(s)
I20260812 06:18:26.523087  4479 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:26.529130  4479 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: Bootstrap starting.
I20260812 06:18:26.531651  4479 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:26.532666  4479 log.cc:826] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:26.534744  4479 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: No bootstrap required, opened a new log
I20260812 06:18:26.537912  4479 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER }
I20260812 06:18:26.538095  4479 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:26.538200  4479 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1dbe5f1d161e4d638a1fedb90dac3716, State: Initialized, Role: FOLLOWER
I20260812 06:18:26.538872  4479 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [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: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER }
I20260812 06:18:26.539057  4479 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:26.539143  4479 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:26.539290  4479 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:26.540177  4479 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER }
I20260812 06:18:26.540665  4479 leader_election.cc:304] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [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: 1dbe5f1d161e4d638a1fedb90dac3716; no voters: 
I20260812 06:18:26.541090  4479 leader_election.cc:290] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:26.541293  4485 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:26.541762  4485 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 1 LEADER]: Becoming Leader. State: Replica: 1dbe5f1d161e4d638a1fedb90dac3716, State: Running, Role: LEADER
I20260812 06:18:26.542255  4479 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:26.542233  4485 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [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: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER }
I20260812 06:18:26.544353  4486 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER } }
I20260812 06:18:26.544502  4486 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:26.544797  4487 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1dbe5f1d161e4d638a1fedb90dac3716. Latest consensus state: current_term: 1 leader_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1dbe5f1d161e4d638a1fedb90dac3716" member_type: VOTER } }
I20260812 06:18:26.544899  4487 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:26.544968  4379 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:26.547325  4508 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:26.547390  4508 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:26.547467  4506 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:26.548218  4506 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:26.553016  4506 catalog_manager.cc:1383] Generated new cluster ID: 87a176efc5474ce789c9aa66673d7cca
I20260812 06:18:26.553124  4506 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:26.564018  4506 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:26.565102  4506 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:26.577098  4506 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: Generated new TSK 0
I20260812 06:18:26.577783  4506 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:26.609818  4379 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:26.612548  4514 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:26.612643  4516 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:26.612941  4519 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:26.613204  4379 server_base.cc:1061] running on GCE node
I20260812 06:18:26.613399  4379 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:26.613448  4379 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:26.613466  4379 hybrid_clock.cc:648] HybridClock initialized: now 1786515506613465 us; error 0 us; skew 500 ppm
I20260812 06:18:26.614501  4379 webserver.cc:533] Webserver started at http://127.4.70.193:34191/ using document root <none> and password file <none>
I20260812 06:18:26.614689  4379 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:26.614746  4379 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:26.614847  4379 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:26.615322  4379 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/instance:
uuid: "5b3765a747fd4cb2834e57e40761ffc8"
format_stamp: "Formatted at 2026-08-12 06:18:26 on dist-test-slave-s11t"
I20260812 06:18:26.616963  4379 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:26.617987  4529 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:26.618256  4379 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:26.618330  4379 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root
uuid: "5b3765a747fd4cb2834e57e40761ffc8"
format_stamp: "Formatted at 2026-08-12 06:18:26 on dist-test-slave-s11t"
I20260812 06:18:26.618425  4379 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:26.651542  4379 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:26.652026  4379 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:26.652556  4379 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:26.653503  4379 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:26.653555  4379 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:26.653601  4379 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:26.653659  4379 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:26.660416  4379 rpc_server.cc:307] RPC server started. Bound to: 127.4.70.193:45529
I20260812 06:18:26.660462  4638 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.70.193:45529 every 8 connection(s)
I20260812 06:18:26.674259  4639 heartbeater.cc:344] Connected to a master server at 127.4.70.254:38107
I20260812 06:18:26.674544  4639 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:26.675034  4639 heartbeater.cc:507] Master 127.4.70.254:38107 requested a full tablet report, sending...
I20260812 06:18:26.676573  4432 ts_manager.cc:194] Registered new tserver with Master: 5b3765a747fd4cb2834e57e40761ffc8 (127.4.70.193:45529)
I20260812 06:18:26.676874  4379 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015746095s
I20260812 06:18:26.678282  4432 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57256
I20260812 06:18:26.687397  4432 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57262:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:26.702273  4585 tablet_service.cc:1511] Processing CreateTablet for tablet 8d65b00c63f748898726a32269ab267f (DEFAULT_TABLE table=heavy-update-compaction-test [id=deb7a22ed0a84b45bae4384687a83197]), partition=
I20260812 06:18:26.702776  4585 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8d65b00c63f748898726a32269ab267f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:26.705457  4656 tablet_bootstrap.cc:492] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Bootstrap starting.
I20260812 06:18:26.706650  4656 tablet_bootstrap.cc:654] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:26.708015  4656 tablet_bootstrap.cc:492] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: No bootstrap required, opened a new log
I20260812 06:18:26.708124  4656 ts_tablet_manager.cc:1403] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:26.708725  4656 raft_consensus.cc:359] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b3765a747fd4cb2834e57e40761ffc8" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 45529 } }
I20260812 06:18:26.708922  4656 raft_consensus.cc:385] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:26.708967  4656 raft_consensus.cc:740] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5b3765a747fd4cb2834e57e40761ffc8, State: Initialized, Role: FOLLOWER
I20260812 06:18:26.709146  4656 consensus_queue.cc:260] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [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: "5b3765a747fd4cb2834e57e40761ffc8" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 45529 } }
I20260812 06:18:26.709252  4656 raft_consensus.cc:399] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:26.709286  4656 raft_consensus.cc:493] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:26.709378  4656 raft_consensus.cc:3060] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:26.710304  4656 raft_consensus.cc:515] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b3765a747fd4cb2834e57e40761ffc8" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 45529 } }
I20260812 06:18:26.710465  4656 leader_election.cc:304] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [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: 5b3765a747fd4cb2834e57e40761ffc8; no voters: 
I20260812 06:18:26.710675  4656 leader_election.cc:290] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:26.710868  4659 raft_consensus.cc:2804] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:26.711012  4656 ts_tablet_manager.cc:1434] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:26.711236  4639 heartbeater.cc:499] Master 127.4.70.254:38107 was elected leader, sending a full tablet report...
I20260812 06:18:26.711608  4659 raft_consensus.cc:697] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 1 LEADER]: Becoming Leader. State: Replica: 5b3765a747fd4cb2834e57e40761ffc8, State: Running, Role: LEADER
I20260812 06:18:26.711777  4659 consensus_queue.cc:237] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [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: "5b3765a747fd4cb2834e57e40761ffc8" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 45529 } }
I20260812 06:18:26.715173  4432 catalog_manager.cc:5719] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5b3765a747fd4cb2834e57e40761ffc8 (127.4.70.193). New cstate: current_term: 1 leader_uuid: "5b3765a747fd4cb2834e57e40761ffc8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5b3765a747fd4cb2834e57e40761ffc8" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 45529 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:26.777838  4379 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.014s	sys 0.011s
I20260812 06:18:26.911640  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushMRSOp(8d65b00c63f748898726a32269ab267f): perf score=18.062753
I20260812 06:18:27.095181  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushMRSOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.183s	user 0.128s	sys 0.052s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":424,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":923,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45402,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":178,"threads_started":1,"update_count":1500}
I20260812 06:18:27.096400  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 20743880 bytes of WAL
I20260812 06:18:27.096933  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 2 log segments from log reader
I20260812 06:18:27.097051  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000001 (ops 1-6)
I20260812 06:18:27.097146  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000002 (ops 7-11)
I20260812 06:18:27.104136  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.007s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:27.104641  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f): 16411395 bytes on disk
I20260812 06:18:27.105448  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.105973  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.140172  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.034s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.140725  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.152463  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.152998  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:27.336974  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.184s	user 0.128s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":621,"lbm_read_time_us":11934,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32175,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":384,"threads_started":5,"update_count":2500}
I20260812 06:18:27.337666  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:27.373966  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.036s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15395,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.374519  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.386432  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.386895  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:27.532855  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.146s	user 0.111s	sys 0.032s 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":1258,"lbm_read_time_us":10478,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26848,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:27.533658  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:27.584512  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.051s	user 0.034s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18442,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:18:27.585125  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.597437  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.597908  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:27.744755  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.147s	user 0.119s	sys 0.028s 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":306,"lbm_read_time_us":10964,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29759,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:18:27.745357  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:27.785601  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19582,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.786084  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.797605  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.798138  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:27.930722  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.132s	user 0.109s	sys 0.021s 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":602,"lbm_read_time_us":9462,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24904,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:18:27.931571  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:27.972132  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.040s	user 0.018s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14346,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:27.972772  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:27.986625  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4738,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.987238  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:28.133054  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.146s	user 0.076s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":9191,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25732,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:28.133666  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:28.168476  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.035s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14222,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.169217  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.181160  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.181715  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:28.310859  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.129s	user 0.111s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":455,"lbm_read_time_us":8474,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27408,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:28.311630  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:28.349936  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16854,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.350534  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.363021  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.363554  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushMRSOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:28.394380  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushMRSOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":296,"dirs.run_wall_time_us":1483,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1833,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:28.395233  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 112239257 bytes of WAL
I20260812 06:18:28.395514  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 11 log segments from log reader
I20260812 06:18:28.395576  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000003 (ops 12-16)
I20260812 06:18:28.395613  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000004 (ops 17-21)
I20260812 06:18:28.395649  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000005 (ops 22-26)
I20260812 06:18:28.395685  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000006 (ops 27-31)
I20260812 06:18:28.395715  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000007 (ops 32-36)
I20260812 06:18:28.395742  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000008 (ops 37-41)
I20260812 06:18:28.395771  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000009 (ops 42-46)
I20260812 06:18:28.395802  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000010 (ops 47-51)
I20260812 06:18:28.395838  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000011 (ops 52-56)
I20260812 06:18:28.395862  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000012 (ops 57-60)
I20260812 06:18:28.395891  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000013 (ops 61-65)
I20260812 06:18:28.423429  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:28.423882  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=3.181125
I20260812 06:18:28.452633  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.029s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7299,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:28.453366  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.468333  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.468968  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f): 463 bytes on disk
I20260812 06:18:28.469515  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.470166  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:28.657078  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.187s	user 0.153s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":211,"lbm_read_time_us":20657,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33918,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:28.657728  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:28.709888  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.052s	user 0.018s	sys 0.033s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23873,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.710358  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.721177  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.721637  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:28.866094  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.144s	user 0.102s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":10735,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31472,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:28.866741  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:28.918838  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.052s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17752,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1550}
I20260812 06:18:28.919312  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.941020  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.021s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.941479  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:28.951237  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3763,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.951666  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:29.114886  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.163s	user 0.134s	sys 0.028s 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":214,"lbm_read_time_us":12444,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29884,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:29.115450  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:29.150885  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.035s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14313,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.151459  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.164332  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.164839  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:29.305445  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.140s	user 0.112s	sys 0.025s 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":434,"lbm_read_time_us":8603,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26113,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.306087  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:29.354022  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.048s	user 0.037s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17522,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.354632  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.376504  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.022s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.377102  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.387176  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.387802  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:29.555155  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1035,"lbm_read_time_us":10819,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29572,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:29.555791  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:29.600896  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.045s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15704,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.601724  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.613142  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.613637  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:29.772226  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.158s	user 0.104s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":10667,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25176,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:29.772863  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:29.811376  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.038s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17261,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.811959  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.829011  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5699,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.829617  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushMRSOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:29.881307  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushMRSOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.051s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1748,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2087,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:29.882130  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 121006488 bytes of WAL
I20260812 06:18:29.882408  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 12 log segments from log reader
I20260812 06:18:29.882470  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000014 (ops 66-70)
I20260812 06:18:29.882509  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000015 (ops 71-75)
I20260812 06:18:29.882539  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000016 (ops 76-80)
I20260812 06:18:29.882571  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000017 (ops 81-85)
I20260812 06:18:29.882604  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000018 (ops 86-90)
I20260812 06:18:29.882633  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000019 (ops 91-94)
I20260812 06:18:29.882678  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000020 (ops 95-99)
I20260812 06:18:29.882709  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000021 (ops 100-104)
I20260812 06:18:29.882740  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000022 (ops 105-109)
I20260812 06:18:29.882781  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000023 (ops 110-114)
I20260812 06:18:29.882807  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000024 (ops 115-119)
I20260812 06:18:29.882836  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000025 (ops 120-124)
I20260812 06:18:29.911008  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:29.911485  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=6.157687
I20260812 06:18:29.937496  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.026s	user 0.012s	sys 0.011s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":11157,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:29.938010  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 12017879 bytes of WAL
I20260812 06:18:29.938228  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 1 log segments from log reader
I20260812 06:18:29.938272  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000026 (ops 125-129)
I20260812 06:18:29.940753  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.003s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:18:29.941051  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f): 472 bytes on disk
I20260812 06:18:29.941454  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f) 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:18:29.941946  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:29.954720  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.955183  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:30.161943  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.207s	user 0.158s	sys 0.048s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":775,"lbm_read_time_us":15936,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36005,"lbm_writes_lt_1ms":743,"mutex_wait_us":97,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:18:30.162753  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:30.214350  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.051s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21512,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.215154  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:30.228169  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.228756  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:30.417131  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.188s	user 0.129s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":15328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32891,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:18:30.417793  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:30.488392  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.070s	user 0.034s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":30822,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.489022  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:30.501405  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.502128  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:30.663560  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.161s	user 0.129s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":133,"lbm_read_time_us":13774,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27875,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:18:30.664175  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=10.126437
I20260812 06:18:30.700102  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.036s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16186,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.700748  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:30.730608  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.030s	user 0.005s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6629,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.731551  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:30.899616  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.168s	user 0.117s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":375,"lbm_read_time_us":9929,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28651,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:18:30.900441  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:30.954993  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.054s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.955515  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:30.966420  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.967096  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:31.122146  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.155s	user 0.128s	sys 0.025s 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":335,"lbm_read_time_us":10635,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29611,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:31.122820  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=11.118625
I20260812 06:18:31.159569  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.037s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16089,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.160167  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:31.179608  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.019s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5801,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.180207  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:31.323062  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.143s	user 0.114s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":7354,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27618,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:18:31.323848  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:31.383723  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.060s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26525,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:31.384312  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:31.402104  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.402771  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushMRSOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:31.455158  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushMRSOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.052s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":285,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2339,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.455943  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 120100634 bytes of WAL
I20260812 06:18:31.456197  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 12 log segments from log reader
I20260812 06:18:31.456248  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000027 (ops 130-134)
I20260812 06:18:31.456281  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000028 (ops 135-138)
I20260812 06:18:31.456348  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000029 (ops 139-143)
I20260812 06:18:31.456387  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000030 (ops 144-148)
I20260812 06:18:31.456439  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000031 (ops 149-153)
I20260812 06:18:31.456477  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000032 (ops 154-158)
I20260812 06:18:31.456519  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000033 (ops 159-162)
I20260812 06:18:31.456563  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000034 (ops 163-167)
I20260812 06:18:31.456606  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000035 (ops 168-172)
I20260812 06:18:31.456646  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000036 (ops 173-177)
I20260812 06:18:31.456728  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000037 (ops 178-182)
I20260812 06:18:31.456791  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000038 (ops 183-186)
I20260812 06:18:31.487139  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:31.487638  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f): 483 bytes on disk
I20260812 06:18:31.488328  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: UndoDeltaBlockGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.489005  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=7.149875
I20260812 06:18:31.512995  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":10271,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:31.513558  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling LogGCOp(8d65b00c63f748898726a32269ab267f): free 8767086 bytes of WAL
I20260812 06:18:31.513810  4542 log_reader.cc:385] T 8d65b00c63f748898726a32269ab267f: removed 1 log segments from log reader
I20260812 06:18:31.513870  4542 log.cc:1079] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/8d65b00c63f748898726a32269ab267f/wal-000000039 (ops 187-191)
I20260812 06:18:31.516094  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: LogGCOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:31.516487  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=2.188937
I20260812 06:18:31.531594  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5642,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.532042  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:31.719246  4379 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.941s	user 1.874s	sys 0.115s
I20260812 06:18:31.742133  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.210s	user 0.160s	sys 0.048s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14795,"lbm_reads_lt_1ms":866,"lbm_write_time_us":46009,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":4000}
I20260812 06:18:31.742614  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f): perf score=14.095187
I20260812 06:18:31.774830  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: FlushDeltaMemStoresOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.032s	user 0.012s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15580,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.775311  4640 maintenance_manager.cc:419] P 5b3765a747fd4cb2834e57e40761ffc8: Scheduling MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f): perf score=1.000000
I20260812 06:18:31.799898  4379 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.001s	sys 0.000s
I20260812 06:18:31.800588  4379 tablet_server.cc:179] TabletServer@127.4.70.193:0 shutting down...
I20260812 06:18:31.886435  4542 maintenance_manager.cc:643] P 5b3765a747fd4cb2834e57e40761ffc8: MajorDeltaCompactionOp(8d65b00c63f748898726a32269ab267f) complete. Timing: real 0.111s	user 0.090s	sys 0.020s 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":326,"lbm_read_time_us":7702,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21776,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":67328,"update_count":2000}
I20260812 06:18:31.887248  4379 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:31.887722  4379 tablet_replica.cc:333] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8: stopping tablet replica
I20260812 06:18:31.887977  4379 raft_consensus.cc:2243] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:31.888217  4379 raft_consensus.cc:2272] T 8d65b00c63f748898726a32269ab267f P 5b3765a747fd4cb2834e57e40761ffc8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:31.904398  4379 tablet_server.cc:196] TabletServer@127.4.70.193:0 shutdown complete.
I20260812 06:18:31.941461  4379 master.cc:562] Master@127.4.70.254:38107 shutting down...
I20260812 06:18:31.945765  4379 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:31.945978  4379 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:31.946061  4379 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1dbe5f1d161e4d638a1fedb90dac3716: stopping tablet replica
I20260812 06:18:31.958691  4379 master.cc:584] Master@127.4.70.254:38107 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5597 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:32.064899  4379 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.70.254:35835
I20260812 06:18:32.065346  4379 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.067961  4680 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:32.068012  4379 server_base.cc:1061] running on GCE node
W20260812 06:18:32.068128  4682 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:32.067993  4679 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:32.068459  4379 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.068519  4379 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:32.068542  4379 hybrid_clock.cc:648] HybridClock initialized: now 1786515512068542 us; error 0 us; skew 500 ppm
I20260812 06:18:32.069530  4379 webserver.cc:533] Webserver started at http://127.4.70.254:38307/ using document root <none> and password file <none>
I20260812 06:18:32.069669  4379 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.069711  4379 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.069767  4379 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.070119  4379 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/master-0-root/instance:
uuid: "736dca0c35414b5bbd4bd4d0adedf383"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-s11t"
I20260812 06:18:32.071646  4379 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:32.072873  4691 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.073179  4379 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:32.073244  4379 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/master-0-root
uuid: "736dca0c35414b5bbd4bd4d0adedf383"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-s11t"
I20260812 06:18:32.073304  4379 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:32.083707  4379 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.084055  4379 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.088593  4379 rpc_server.cc:307] RPC server started. Bound to: 127.4.70.254:35835
I20260812 06:18:32.092336  4774 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.092973  4773 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.70.254:35835 every 8 connection(s)
I20260812 06:18:32.097203  4774 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383: Bootstrap starting.
I20260812 06:18:32.098057  4774 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.099525  4774 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383: No bootstrap required, opened a new log
I20260812 06:18:32.100026  4774 raft_consensus.cc:359] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER }
I20260812 06:18:32.100154  4774 raft_consensus.cc:385] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.100226  4774 raft_consensus.cc:740] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 736dca0c35414b5bbd4bd4d0adedf383, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.100418  4774 consensus_queue.cc:260] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [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: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER }
I20260812 06:18:32.100525  4774 raft_consensus.cc:399] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.100574  4774 raft_consensus.cc:493] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.100634  4774 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.101486  4774 raft_consensus.cc:515] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER }
I20260812 06:18:32.101670  4774 leader_election.cc:304] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [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: 736dca0c35414b5bbd4bd4d0adedf383; no voters: 
I20260812 06:18:32.101905  4774 leader_election.cc:290] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.102061  4777 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.102342  4777 raft_consensus.cc:697] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 1 LEADER]: Becoming Leader. State: Replica: 736dca0c35414b5bbd4bd4d0adedf383, State: Running, Role: LEADER
I20260812 06:18:32.102471  4774 sys_catalog.cc:565] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:32.102522  4777 consensus_queue.cc:237] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [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: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER }
I20260812 06:18:32.103066  4778 sys_catalog.cc:455] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "736dca0c35414b5bbd4bd4d0adedf383" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER } }
I20260812 06:18:32.103093  4779 sys_catalog.cc:455] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 736dca0c35414b5bbd4bd4d0adedf383. Latest consensus state: current_term: 1 leader_uuid: "736dca0c35414b5bbd4bd4d0adedf383" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "736dca0c35414b5bbd4bd4d0adedf383" member_type: VOTER } }
I20260812 06:18:32.103225  4778 sys_catalog.cc:458] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.103341  4779 sys_catalog.cc:458] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.103837  4787 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:32.104660  4787 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:32.104998  4379 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:32.106632  4787 catalog_manager.cc:1383] Generated new cluster ID: a7fbf4393ba34f3db05ad798723fdbd0
I20260812 06:18:32.106693  4787 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:32.120332  4787 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:32.120976  4787 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:32.135689  4787 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383: Generated new TSK 0
I20260812 06:18:32.135883  4787 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:32.137490  4379 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.139516  4806 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:32.139511  4809 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:32.139530  4801 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:32.139760  4379 server_base.cc:1061] running on GCE node
I20260812 06:18:32.139998  4379 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.140067  4379 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:32.140085  4379 hybrid_clock.cc:648] HybridClock initialized: now 1786515512140085 us; error 0 us; skew 500 ppm
I20260812 06:18:32.141007  4379 webserver.cc:533] Webserver started at http://127.4.70.193:46173/ using document root <none> and password file <none>
I20260812 06:18:32.141189  4379 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.141254  4379 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.141336  4379 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.141768  4379 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/instance:
uuid: "353a9bb450cc4025a358de4bce470e46"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-s11t"
I20260812 06:18:32.143301  4379 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:32.144258  4818 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.144533  4379 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:32.144604  4379 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root
uuid: "353a9bb450cc4025a358de4bce470e46"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-s11t"
I20260812 06:18:32.144661  4379 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:32.165835  4379 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.166208  4379 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.166466  4379 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:32.166980  4379 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:32.167021  4379 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.167055  4379 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:32.167070  4379 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.171530  4379 rpc_server.cc:307] RPC server started. Bound to: 127.4.70.193:39729
I20260812 06:18:32.171615  4905 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.70.193:39729 every 8 connection(s)
I20260812 06:18:32.181814  4907 heartbeater.cc:344] Connected to a master server at 127.4.70.254:35835
I20260812 06:18:32.181967  4907 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:32.182260  4907 heartbeater.cc:507] Master 127.4.70.254:35835 requested a full tablet report, sending...
I20260812 06:18:32.183024  4719 ts_manager.cc:194] Registered new tserver with Master: 353a9bb450cc4025a358de4bce470e46 (127.4.70.193:39729)
I20260812 06:18:32.183111  4379 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011138077s
I20260812 06:18:32.184087  4719 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58816
I20260812 06:18:32.191056  4719 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58820:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:32.200495  4860 tablet_service.cc:1511] Processing CreateTablet for tablet 1dc04fae124f4f6eb374949246207c6c (DEFAULT_TABLE table=heavy-update-compaction-test [id=949ed3f4856e4cdb8cf14a11109d00e6]), partition=
I20260812 06:18:32.200850  4860 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1dc04fae124f4f6eb374949246207c6c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.203154  4931 tablet_bootstrap.cc:492] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Bootstrap starting.
I20260812 06:18:32.203938  4931 tablet_bootstrap.cc:654] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.205123  4931 tablet_bootstrap.cc:492] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: No bootstrap required, opened a new log
I20260812 06:18:32.205235  4931 ts_tablet_manager.cc:1403] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:32.205744  4931 raft_consensus.cc:359] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "353a9bb450cc4025a358de4bce470e46" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 39729 } }
I20260812 06:18:32.205876  4931 raft_consensus.cc:385] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.205925  4931 raft_consensus.cc:740] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 353a9bb450cc4025a358de4bce470e46, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.206066  4931 consensus_queue.cc:260] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [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: "353a9bb450cc4025a358de4bce470e46" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 39729 } }
I20260812 06:18:32.206187  4931 raft_consensus.cc:399] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.206233  4931 raft_consensus.cc:493] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.206290  4931 raft_consensus.cc:3060] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.206996  4931 raft_consensus.cc:515] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "353a9bb450cc4025a358de4bce470e46" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 39729 } }
I20260812 06:18:32.207151  4931 leader_election.cc:304] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [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: 353a9bb450cc4025a358de4bce470e46; no voters: 
I20260812 06:18:32.207367  4931 leader_election.cc:290] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.207508  4938 raft_consensus.cc:2804] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.207722  4931 ts_tablet_manager.cc:1434] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:32.207803  4907 heartbeater.cc:499] Master 127.4.70.254:35835 was elected leader, sending a full tablet report...
I20260812 06:18:32.207824  4938 raft_consensus.cc:697] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 1 LEADER]: Becoming Leader. State: Replica: 353a9bb450cc4025a358de4bce470e46, State: Running, Role: LEADER
I20260812 06:18:32.208029  4938 consensus_queue.cc:237] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [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: "353a9bb450cc4025a358de4bce470e46" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 39729 } }
I20260812 06:18:32.209534  4719 catalog_manager.cc:5719] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 reported cstate change: term changed from 0 to 1, leader changed from <none> to 353a9bb450cc4025a358de4bce470e46 (127.4.70.193). New cstate: current_term: 1 leader_uuid: "353a9bb450cc4025a358de4bce470e46" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "353a9bb450cc4025a358de4bce470e46" member_type: VOTER last_known_addr { host: "127.4.70.193" port: 39729 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:32.274663  4379 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.008s
I20260812 06:18:32.422464  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushMRSOp(1dc04fae124f4f6eb374949246207c6c): perf score=19.054940
I20260812 06:18:32.577107  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushMRSOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.154s	user 0.103s	sys 0.051s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":790,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38710,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:32.577785  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling LogGCOp(1dc04fae124f4f6eb374949246207c6c): free 20743880 bytes of WAL
I20260812 06:18:32.578034  4824 log_reader.cc:385] T 1dc04fae124f4f6eb374949246207c6c: removed 2 log segments from log reader
I20260812 06:18:32.578094  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000001 (ops 1-6)
I20260812 06:18:32.578136  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000002 (ops 7-11)
I20260812 06:18:32.583971  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: LogGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:32.584415  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:32.602090  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.602553  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:32.754230  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.151s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":67,"lbm_read_time_us":11370,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25042,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"thread_start_us":307,"threads_started":5,"update_count":2000}
I20260812 06:18:32.755064  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c): 16411397 bytes on disk
I20260812 06:18:32.755484  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.756069  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=11.118625
I20260812 06:18:32.799034  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.043s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16275,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.799539  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:32.824882  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.025s	user 0.010s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.825419  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:32.835443  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.836026  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:33.014943  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.179s	user 0.111s	sys 0.066s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1203,"lbm_read_time_us":12637,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30197,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:33.015829  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:33.070545  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24050,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.071036  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.092536  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.021s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.093148  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:33.288089  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.195s	user 0.141s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":14825,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31568,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:33.288787  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:33.331429  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.042s	user 0.010s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19059,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.331969  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.345011  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.345736  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:33.532722  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.187s	user 0.116s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":897,"lbm_read_time_us":11959,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31901,"lbm_writes_lt_1ms":543,"mutex_wait_us":181,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:33.533488  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=11.118625
I20260812 06:18:33.573933  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.040s	user 0.016s	sys 0.022s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17545,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.574533  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.591085  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.016s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.591538  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.602154  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.602752  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:33.763548  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.161s	user 0.128s	sys 0.030s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":12375,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32276,"lbm_writes_lt_1ms":543,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:33.765456  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=11.118625
I20260812 06:18:33.804143  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.038s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16436,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.805135  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.832463  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5683,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.833011  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.843961  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.844543  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushMRSOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:33.874181  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushMRSOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.029s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1548,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1657,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:33.874879  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling LogGCOp(1dc04fae124f4f6eb374949246207c6c): free 112239307 bytes of WAL
I20260812 06:18:33.875149  4824 log_reader.cc:385] T 1dc04fae124f4f6eb374949246207c6c: removed 11 log segments from log reader
I20260812 06:18:33.875211  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000003 (ops 12-16)
I20260812 06:18:33.875252  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000004 (ops 17-21)
I20260812 06:18:33.875274  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000005 (ops 22-26)
I20260812 06:18:33.875295  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000006 (ops 27-31)
I20260812 06:18:33.875339  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000007 (ops 32-36)
I20260812 06:18:33.875370  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000008 (ops 37-41)
I20260812 06:18:33.875402  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000009 (ops 42-46)
I20260812 06:18:33.875432  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000010 (ops 47-50)
I20260812 06:18:33.875459  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000011 (ops 51-55)
I20260812 06:18:33.875494  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000012 (ops 56-60)
I20260812 06:18:33.875520  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000013 (ops 61-65)
I20260812 06:18:33.905561  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: LogGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:33.906045  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c): 462 bytes on disk
I20260812 06:18:33.906633  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.907181  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.931574  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.932078  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling LogGCOp(1dc04fae124f4f6eb374949246207c6c): free 12017932 bytes of WAL
I20260812 06:18:33.932288  4824 log_reader.cc:385] T 1dc04fae124f4f6eb374949246207c6c: removed 1 log segments from log reader
I20260812 06:18:33.932338  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000014 (ops 66-70)
I20260812 06:18:33.934804  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: LogGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:33.935097  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:33.956334  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.021s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.956921  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:34.231988  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.275s	user 0.182s	sys 0.089s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2610,"lbm_read_time_us":17841,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44488,"lbm_writes_lt_1ms":743,"mutex_wait_us":298,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:18:34.242528  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=18.063937
I20260812 06:18:34.315629  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.073s	user 0.043s	sys 0.027s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32652,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:34.316102  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=3.181125
I20260812 06:18:34.328364  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.328909  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:34.342479  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5103,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.343050  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:34.561946  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.219s	user 0.138s	sys 0.079s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979623,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":228,"lbm_read_time_us":16840,"lbm_reads_lt_1ms":773,"lbm_write_time_us":38390,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3500}
I20260812 06:18:34.562840  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=18.063937
I20260812 06:18:34.625559  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.063s	user 0.042s	sys 0.020s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":26775,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:34.626371  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:34.654610  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.028s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.655200  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:34.671037  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.671646  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:34.870045  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.198s	user 0.145s	sys 0.052s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979638,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":765,"lbm_read_time_us":16885,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39188,"lbm_writes_lt_1ms":743,"mutex_wait_us":417,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3500}
I20260812 06:18:34.870875  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:34.925330  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.054s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23903,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.925936  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=3.181125
I20260812 06:18:34.948257  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.020s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5632,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.948837  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:34.962226  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.962720  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:35.135378  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.172s	user 0.124s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1253,"lbm_read_time_us":13985,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34501,"lbm_writes_lt_1ms":643,"mutex_wait_us":279,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3000}
I20260812 06:18:35.136071  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=11.118625
I20260812 06:18:35.177783  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.041s	user 0.037s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18181,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:35.178365  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:35.192948  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5400,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.193398  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:35.316298  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.123s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":838,"lbm_read_time_us":8416,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25637,"lbm_writes_lt_1ms":443,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:35.316968  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=10.126437
I20260812 06:18:35.374681  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.058s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17913,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.375260  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:35.387080  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.012s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.387718  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushMRSOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:35.424404  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushMRSOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.036s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1331,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1564,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:35.425078  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling LogGCOp(1dc04fae124f4f6eb374949246207c6c): free 121006384 bytes of WAL
I20260812 06:18:35.425307  4824 log_reader.cc:385] T 1dc04fae124f4f6eb374949246207c6c: removed 12 log segments from log reader
I20260812 06:18:35.425354  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000015 (ops 71-75)
I20260812 06:18:35.425382  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000016 (ops 76-80)
I20260812 06:18:35.425441  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000017 (ops 81-84)
I20260812 06:18:35.425490  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000018 (ops 85-89)
I20260812 06:18:35.425527  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000019 (ops 90-94)
I20260812 06:18:35.425590  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000020 (ops 95-99)
I20260812 06:18:35.425627  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000021 (ops 100-104)
I20260812 06:18:35.425668  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000022 (ops 105-109)
I20260812 06:18:35.425709  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000023 (ops 110-114)
I20260812 06:18:35.425750  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000024 (ops 115-119)
I20260812 06:18:35.425791  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000025 (ops 120-124)
I20260812 06:18:35.425832  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000026 (ops 125-129)
I20260812 06:18:35.452450  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: LogGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:35.452960  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=3.181125
I20260812 06:18:35.475342  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.022s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6525,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:35.475841  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:35.486027  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.486646  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:35.697052  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.210s	user 0.144s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":479,"lbm_read_time_us":12890,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34131,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:35.698004  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c): 472 bytes on disk
I20260812 06:18:35.698746  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c) 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:18:35.699334  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=16.079562
I20260812 06:18:35.761754  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.062s	user 0.033s	sys 0.019s Metrics: {"bytes_written":18502130,"delete_count":0,"lbm_write_time_us":24375,"lbm_writes_lt_1ms":454,"mutex_wait_us":17,"reinsert_count":0,"update_count":2255}
I20260812 06:18:35.762279  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=4.173312
I20260812 06:18:35.779340  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":6112855,"delete_count":0,"lbm_write_time_us":6918,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:18:35.779992  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:35.990877  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.211s	user 0.139s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":407,"lbm_read_time_us":15792,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37085,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:18:35.991690  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:36.046250  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.054s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25150,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.046723  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=3.181125
I20260812 06:18:36.067152  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.020s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:36.067654  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.078275  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3764,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.078749  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:36.304073  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.225s	user 0.169s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1212,"lbm_read_time_us":17123,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37311,"lbm_writes_lt_1ms":643,"mutex_wait_us":359,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":35712,"update_count":3000}
I20260812 06:18:36.304805  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:36.361013  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.056s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26342,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.361662  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.375352  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.375998  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:36.554809  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.179s	user 0.106s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":812,"lbm_read_time_us":13282,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29653,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2500}
I20260812 06:18:36.557997  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:36.607172  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.049s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.607662  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.619508  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.620909  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:36.815006  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.194s	user 0.119s	sys 0.068s 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":630,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32349,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:36.815727  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=14.095187
I20260812 06:18:36.878647  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.062s	user 0.036s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21398,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.879151  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.890153  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.890604  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushMRSOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:36.936133  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushMRSOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.045s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1212,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2271,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:36.936934  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling LogGCOp(1dc04fae124f4f6eb374949246207c6c): free 112692675 bytes of WAL
I20260812 06:18:36.937206  4824 log_reader.cc:385] T 1dc04fae124f4f6eb374949246207c6c: removed 11 log segments from log reader
I20260812 06:18:36.937297  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000027 (ops 130-134)
I20260812 06:18:36.937348  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000028 (ops 135-139)
I20260812 06:18:36.937407  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000029 (ops 140-144)
I20260812 06:18:36.937450  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000030 (ops 145-149)
I20260812 06:18:36.937492  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000031 (ops 150-154)
I20260812 06:18:36.937531  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000032 (ops 155-159)
I20260812 06:18:36.937569  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000033 (ops 160-164)
I20260812 06:18:36.937608  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000034 (ops 165-169)
I20260812 06:18:36.937647  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000035 (ops 170-174)
I20260812 06:18:36.937686  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000036 (ops 175-179)
I20260812 06:18:36.937724  4824 log.cc:1079] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: Deleting log segment in path: /tmp/dist-test-task17we3F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515506443070-4379-0/minicluster-data/ts-0-root/wals/1dc04fae124f4f6eb374949246207c6c/wal-000000037 (ops 180-184)
I20260812 06:18:36.961928  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: LogGCOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:36.962397  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c): 463 bytes on disk
I20260812 06:18:36.962888  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: UndoDeltaBlockGCOp(1dc04fae124f4f6eb374949246207c6c) 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:18:36.963436  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.984745  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.021s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.985230  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:36.995426  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.995935  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:37.227891  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.232s	user 0.159s	sys 0.062s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":672,"lbm_read_time_us":15082,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40404,"lbm_writes_lt_1ms":743,"mutex_wait_us":254,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:18:37.228608  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=18.063937
I20260812 06:18:37.282373  4379 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.008s	user 1.813s	sys 0.171s
I20260812 06:18:37.285737  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.056s	user 0.028s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23408,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:37.286173  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c): perf score=2.188937
I20260812 06:18:37.295887  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: FlushDeltaMemStoresOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.296311  4908 maintenance_manager.cc:419] P 353a9bb450cc4025a358de4bce470e46: Scheduling MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c): perf score=1.000000
I20260812 06:18:37.339097  4379 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.002s	sys 0.000s
I20260812 06:18:37.339727  4379 tablet_server.cc:179] TabletServer@127.4.70.193:0 shutting down...
I20260812 06:18:37.448494  4824 maintenance_manager.cc:643] P 353a9bb450cc4025a358de4bce470e46: MajorDeltaCompactionOp(1dc04fae124f4f6eb374949246207c6c) complete. Timing: real 0.152s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_hit":370,"cfile_cache_hit_bytes":15139741,"cfile_cache_miss":262,"cfile_cache_miss_bytes":13737362,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":440,"lbm_read_time_us":5283,"lbm_reads_lt_1ms":294,"lbm_write_time_us":30590,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23168,"update_count":3000}
I20260812 06:18:37.449287  4379 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:37.449518  4379 tablet_replica.cc:333] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46: stopping tablet replica
I20260812 06:18:37.449678  4379 raft_consensus.cc:2243] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.449875  4379 raft_consensus.cc:2272] T 1dc04fae124f4f6eb374949246207c6c P 353a9bb450cc4025a358de4bce470e46 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.453574  4379 tablet_server.cc:196] TabletServer@127.4.70.193:0 shutdown complete.
I20260812 06:18:37.501190  4379 master.cc:562] Master@127.4.70.254:35835 shutting down...
I20260812 06:18:37.505124  4379 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.505329  4379 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.505424  4379 tablet_replica.cc:333] T 00000000000000000000000000000000 P 736dca0c35414b5bbd4bd4d0adedf383: stopping tablet replica
I20260812 06:18:37.517824  4379 master.cc:584] Master@127.4.70.254:35835 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5560 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11159 ms total)

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