[==========] 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:40.847395  5811 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.172.254:36363
I20260812 06:18:40.848382  5811 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:40.848937  5811 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:40.855659  5811 server_base.cc:1061] running on GCE node
W20260812 06:18:40.855719  5821 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:40.855885  5818 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:40.855963  5819 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:40.856448  5811 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.856539  5811 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:40.856563  5811 hybrid_clock.cc:648] HybridClock initialized: now 1786515520856562 us; error 0 us; skew 500 ppm
I20260812 06:18:40.858290  5811 webserver.cc:533] Webserver started at http://127.5.172.254:35293/ using document root <none> and password file <none>
I20260812 06:18:40.858866  5811 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.858925  5811 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.859108  5811 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.860702  5811 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/master-0-root/instance:
uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-zpfg"
I20260812 06:18:40.864383  5811 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.002s
I20260812 06:18:40.866683  5826 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:40.867941  5811 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:18:40.868044  5811 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/master-0-root
uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-zpfg"
I20260812 06:18:40.868127  5811 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-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:40.901227  5811 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.901942  5811 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:40.902104  5811 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.911165  5811 rpc_server.cc:307] RPC server started. Bound to: 127.5.172.254:36363
I20260812 06:18:40.911209  5882 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.172.254:36363 every 8 connection(s)
I20260812 06:18:40.913861  5883 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:40.920121  5883 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: Bootstrap starting.
I20260812 06:18:40.922839  5883 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.923833  5883 log.cc:826] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:40.926046  5883 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: No bootstrap required, opened a new log
I20260812 06:18:40.929201  5883 raft_consensus.cc:359] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER }
I20260812 06:18:40.929399  5883 raft_consensus.cc:385] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.929453  5883 raft_consensus.cc:740] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a0cb633a1dca4a18aa4a4be11ea2a56c, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.930047  5883 consensus_queue.cc:260] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [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: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER }
I20260812 06:18:40.930198  5883 raft_consensus.cc:399] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.930243  5883 raft_consensus.cc:493] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.930393  5883 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.931284  5883 raft_consensus.cc:515] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER }
I20260812 06:18:40.931754  5883 leader_election.cc:304] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [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: a0cb633a1dca4a18aa4a4be11ea2a56c; no voters: 
I20260812 06:18:40.932106  5883 leader_election.cc:290] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.932332  5886 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.932623  5886 raft_consensus.cc:697] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 1 LEADER]: Becoming Leader. State: Replica: a0cb633a1dca4a18aa4a4be11ea2a56c, State: Running, Role: LEADER
I20260812 06:18:40.933079  5886 consensus_queue.cc:237] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [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: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER }
I20260812 06:18:40.933327  5883 sys_catalog.cc:565] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.935242  5887 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER } }
I20260812 06:18:40.935281  5888 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [sys.catalog]: SysCatalogTable state changed. Reason: New leader a0cb633a1dca4a18aa4a4be11ea2a56c. Latest consensus state: current_term: 1 leader_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cb633a1dca4a18aa4a4be11ea2a56c" member_type: VOTER } }
I20260812 06:18:40.935422  5887 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.935467  5888 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.935883  5811 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.936065  5902 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.938505  5902 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.943656  5902 catalog_manager.cc:1383] Generated new cluster ID: aec5f45db53f464c9e297784efda4a7d
I20260812 06:18:40.943759  5902 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.969782  5902 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.970862  5902 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.984508  5902 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: Generated new TSK 0
I20260812 06:18:40.985311  5902 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:41.001008  5811 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.004487  5908 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:41.004709  5811 server_base.cc:1061] running on GCE node
W20260812 06:18:41.004670  5909 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:41.004902  5911 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.005151  5811 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.005208  5811 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.005231  5811 hybrid_clock.cc:648] HybridClock initialized: now 1786515521005231 us; error 0 us; skew 500 ppm
I20260812 06:18:41.006251  5811 webserver.cc:533] Webserver started at http://127.5.172.193:41953/ using document root <none> and password file <none>
I20260812 06:18:41.006462  5811 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.006528  5811 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.006616  5811 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.007136  5811 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/instance:
uuid: "c6df05db5d434c4dacc329618cbb9abe"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-zpfg"
I20260812 06:18:41.009092  5811 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:41.010311  5916 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.010685  5811 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:41.010811  5811 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root
uuid: "c6df05db5d434c4dacc329618cbb9abe"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-zpfg"
I20260812 06:18:41.010916  5811 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-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:41.038518  5811 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.038972  5811 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.039499  5811 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:41.040385  5811 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:41.040460  5811 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.040541  5811 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:41.040592  5811 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.047372  5811 rpc_server.cc:307] RPC server started. Bound to: 127.5.172.193:41535
I20260812 06:18:41.047412  5983 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.172.193:41535 every 8 connection(s)
I20260812 06:18:41.058277  5984 heartbeater.cc:344] Connected to a master server at 127.5.172.254:36363
I20260812 06:18:41.058571  5984 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:41.059124  5984 heartbeater.cc:507] Master 127.5.172.254:36363 requested a full tablet report, sending...
I20260812 06:18:41.061038  5845 ts_manager.cc:194] Registered new tserver with Master: c6df05db5d434c4dacc329618cbb9abe (127.5.172.193:41535)
I20260812 06:18:41.061801  5811 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013784985s
I20260812 06:18:41.062718  5845 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59602
I20260812 06:18:41.072844  5845 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59618:
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:41.088086  5946 tablet_service.cc:1511] Processing CreateTablet for tablet 25357abc5ac1468ea2fefde4b0f3f86d (DEFAULT_TABLE table=heavy-update-compaction-test [id=c38dbb95b1fc4764956292770c2fc401]), partition=
I20260812 06:18:41.088624  5946 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 25357abc5ac1468ea2fefde4b0f3f86d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.091813  5997 tablet_bootstrap.cc:492] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Bootstrap starting.
I20260812 06:18:41.093205  5997 tablet_bootstrap.cc:654] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.094735  5997 tablet_bootstrap.cc:492] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: No bootstrap required, opened a new log
I20260812 06:18:41.094878  5997 ts_tablet_manager.cc:1403] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:41.095454  5997 raft_consensus.cc:359] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c6df05db5d434c4dacc329618cbb9abe" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 41535 } }
I20260812 06:18:41.095588  5997 raft_consensus.cc:385] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.095636  5997 raft_consensus.cc:740] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c6df05db5d434c4dacc329618cbb9abe, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.095781  5997 consensus_queue.cc:260] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [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: "c6df05db5d434c4dacc329618cbb9abe" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 41535 } }
I20260812 06:18:41.095853  5997 raft_consensus.cc:399] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.095925  5997 raft_consensus.cc:493] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.095980  5997 raft_consensus.cc:3060] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.096740  5997 raft_consensus.cc:515] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c6df05db5d434c4dacc329618cbb9abe" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 41535 } }
I20260812 06:18:41.096900  5997 leader_election.cc:304] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [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: c6df05db5d434c4dacc329618cbb9abe; no voters: 
I20260812 06:18:41.097149  5997 leader_election.cc:290] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.097262  5999 raft_consensus.cc:2804] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.097509  5999 raft_consensus.cc:697] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 1 LEADER]: Becoming Leader. State: Replica: c6df05db5d434c4dacc329618cbb9abe, State: Running, Role: LEADER
I20260812 06:18:41.097543  5997 ts_tablet_manager.cc:1434] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:41.097733  5984 heartbeater.cc:499] Master 127.5.172.254:36363 was elected leader, sending a full tablet report...
I20260812 06:18:41.097730  5999 consensus_queue.cc:237] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [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: "c6df05db5d434c4dacc329618cbb9abe" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 41535 } }
I20260812 06:18:41.101037  5845 catalog_manager.cc:5719] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe reported cstate change: term changed from 0 to 1, leader changed from <none> to c6df05db5d434c4dacc329618cbb9abe (127.5.172.193). New cstate: current_term: 1 leader_uuid: "c6df05db5d434c4dacc329618cbb9abe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c6df05db5d434c4dacc329618cbb9abe" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 41535 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:41.163911  5811 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.008s
I20260812 06:18:41.298589  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=15.086190
I20260812 06:18:41.456513  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.157s	user 0.115s	sys 0.037s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":421,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":976,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38615,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":142,"threads_started":1,"update_count":1450}
I20260812 06:18:41.457865  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d): free 20743880 bytes of WAL
I20260812 06:18:41.458196  5921 log_reader.cc:385] T 25357abc5ac1468ea2fefde4b0f3f86d: removed 2 log segments from log reader
I20260812 06:18:41.458280  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000001 (ops 1-6)
I20260812 06:18:41.458369  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000002 (ops 7-11)
I20260812 06:18:41.464074  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.006s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:18:41.464526  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:41.497241  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.033s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.497756  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:41.512293  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.512822  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:41.658830  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.146s	user 0.087s	sys 0.058s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364568,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1513,"lbm_read_time_us":9468,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27424,"lbm_writes_lt_1ms":533,"mutex_wait_us":311,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":356,"threads_started":5,"update_count":2450}
I20260812 06:18:41.659387  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d): 12719216 bytes on disk
I20260812 06:18:41.659983  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.660456  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:41.697610  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.037s	user 0.007s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.698122  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:41.712760  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.713397  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:41.842873  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.129s	user 0.096s	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":940,"lbm_read_time_us":9639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24986,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:41.843502  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:41.885249  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.042s	user 0.011s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17832,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.885726  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:41.897894  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.898536  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.028765  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.130s	user 0.112s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":9922,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23210,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:42.029340  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:42.080610  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.051s	user 0.032s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19133,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.081202  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:42.092386  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.092854  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.257540  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.165s	user 0.127s	sys 0.027s 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":199,"lbm_read_time_us":10558,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27253,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:42.258278  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:42.307523  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.049s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16084,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.307999  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:42.319226  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.319700  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.444967  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.125s	user 0.113s	sys 0.012s 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":249,"lbm_read_time_us":7550,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24079,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:42.445529  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:42.489203  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.043s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17629,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.489756  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:42.502326  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.503041  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.636301  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.133s	user 0.105s	sys 0.028s 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":171,"lbm_read_time_us":10851,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22940,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:18:42.637148  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:42.682878  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.045s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.683423  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:42.694231  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.694741  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.735853  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.041s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1327,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:42.736740  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d): free 112239261 bytes of WAL
I20260812 06:18:42.736984  5921 log_reader.cc:385] T 25357abc5ac1468ea2fefde4b0f3f86d: removed 11 log segments from log reader
I20260812 06:18:42.737030  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000003 (ops 12-16)
I20260812 06:18:42.737059  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000004 (ops 17-21)
I20260812 06:18:42.737121  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000005 (ops 22-26)
I20260812 06:18:42.737164  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000006 (ops 27-30)
I20260812 06:18:42.737228  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000007 (ops 31-35)
I20260812 06:18:42.737257  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000008 (ops 36-40)
I20260812 06:18:42.737313  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000009 (ops 41-45)
I20260812 06:18:42.737350  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000010 (ops 46-50)
I20260812 06:18:42.737389  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000011 (ops 51-55)
I20260812 06:18:42.737428  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000012 (ops 56-60)
I20260812 06:18:42.737470  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000013 (ops 61-65)
I20260812 06:18:42.761343  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:42.761746  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=3.181125
I20260812 06:18:42.787433  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.025s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6630,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.787947  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:42.797520  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3567,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.798032  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d): 447 bytes on disk
I20260812 06:18:42.798544  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.799000  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:42.997198  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.198s	user 0.137s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":828,"lbm_read_time_us":14268,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32297,"lbm_writes_lt_1ms":643,"mutex_wait_us":120,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:42.997759  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:43.059806  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.062s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23801,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.060396  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:43.072194  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.073109  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:43.263896  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.190s	user 0.134s	sys 0.048s 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":536,"lbm_read_time_us":13659,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30092,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:43.264571  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:43.322062  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.057s	user 0.013s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19276,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.322620  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:43.333446  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.333990  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:43.501708  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.168s	user 0.121s	sys 0.043s 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":1135,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28366,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":72320,"update_count":2500}
I20260812 06:18:43.502611  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:43.535264  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13971,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.537459  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:43.556720  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.557324  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:43.704869  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.147s	user 0.083s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":417,"lbm_read_time_us":10498,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24046,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.706223  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:43.751820  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.045s	user 0.035s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20139,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.752345  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:43.765414  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.765900  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:43.916277  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.150s	user 0.113s	sys 0.036s 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":1122,"lbm_read_time_us":12577,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28726,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":2000}
I20260812 06:18:43.916983  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:43.962082  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.045s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15310,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.962646  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:43.974713  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.975584  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:44.112700  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.137s	user 0.104s	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":827,"lbm_read_time_us":8470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27162,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:44.113346  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:44.169505  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.056s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21319,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.170132  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:44.181962  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.182794  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:44.232803  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.050s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1618,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2555,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:44.233744  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d): free 120100381 bytes of WAL
I20260812 06:18:44.234163  5921 log_reader.cc:385] T 25357abc5ac1468ea2fefde4b0f3f86d: removed 12 log segments from log reader
I20260812 06:18:44.234251  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000014 (ops 66-70)
I20260812 06:18:44.234426  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000015 (ops 71-75)
I20260812 06:18:44.234498  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000016 (ops 76-80)
I20260812 06:18:44.234542  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000017 (ops 81-84)
I20260812 06:18:44.234580  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000018 (ops 85-89)
I20260812 06:18:44.234618  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000019 (ops 90-94)
I20260812 06:18:44.234658  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000020 (ops 95-98)
I20260812 06:18:44.234694  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000021 (ops 99-103)
I20260812 06:18:44.234730  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000022 (ops 104-108)
I20260812 06:18:44.234781  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000023 (ops 109-113)
I20260812 06:18:44.234825  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000024 (ops 114-118)
I20260812 06:18:44.234864  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000025 (ops 119-122)
I20260812 06:18:44.262893  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:44.263351  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=3.181125
I20260812 06:18:44.278028  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.278584  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:44.290076  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.291003  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:44.498721  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.207s	user 0.129s	sys 0.076s 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":6263,"lbm_read_time_us":13229,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34628,"lbm_writes_lt_1ms":643,"mutex_wait_us":2755,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:18:44.499729  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d): 448 bytes on disk
I20260812 06:18:44.500258  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.500909  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:44.556901  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.056s	user 0.020s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24088,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.557394  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:44.568240  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.569150  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:44.743235  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.174s	user 0.101s	sys 0.072s 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":371,"lbm_read_time_us":11965,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29054,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:44.743949  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:44.802601  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.058s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22141,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.803220  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:44.820627  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.821151  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:45.004662  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.183s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":174,"lbm_read_time_us":13215,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29126,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:18:45.005221  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:45.072839  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.067s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23560,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.073400  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.085062  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.085688  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:45.277386  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.192s	user 0.148s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":15827,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":33485,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:45.278102  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=11.118625
I20260812 06:18:45.307734  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.029s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12596,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.308317  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.322444  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4969,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.322914  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:45.477541  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.154s	user 0.125s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":9139,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25691,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:18:45.478370  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:45.519939  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.041s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16039,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.520601  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.544415  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.024s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.544881  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.555366  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.555835  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:45.691718  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.136s	user 0.098s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":686,"lbm_read_time_us":9711,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26587,"lbm_writes_lt_1ms":543,"mutex_wait_us":239,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.692589  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:45.734721  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.042s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18060,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.735313  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.746162  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.746742  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:45.781733  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushMRSOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1595,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2118,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:45.782543  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d): free 121006613 bytes of WAL
I20260812 06:18:45.782780  5921 log_reader.cc:385] T 25357abc5ac1468ea2fefde4b0f3f86d: removed 12 log segments from log reader
I20260812 06:18:45.782826  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000026 (ops 123-127)
I20260812 06:18:45.782856  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000027 (ops 128-132)
I20260812 06:18:45.782924  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000028 (ops 133-137)
I20260812 06:18:45.782959  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000029 (ops 138-142)
I20260812 06:18:45.782995  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000030 (ops 143-147)
I20260812 06:18:45.783068  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000031 (ops 148-152)
I20260812 06:18:45.783111  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000032 (ops 153-157)
I20260812 06:18:45.783151  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000033 (ops 158-162)
I20260812 06:18:45.783197  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000034 (ops 163-166)
I20260812 06:18:45.783237  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000035 (ops 167-171)
I20260812 06:18:45.783278  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000036 (ops 172-176)
I20260812 06:18:45.783326  5921 log.cc:1079] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/25357abc5ac1468ea2fefde4b0f3f86d/wal-000000037 (ops 177-181)
I20260812 06:18:45.807811  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: LogGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:45.808346  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d): 472 bytes on disk
I20260812 06:18:45.808825  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: UndoDeltaBlockGCOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.809428  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.825675  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.826122  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:45.836663  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.837126  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:46.018913  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.182s	user 0.135s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":646,"lbm_read_time_us":11339,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38080,"lbm_writes_lt_1ms":643,"mutex_wait_us":284,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:46.021035  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=14.095187
I20260812 06:18:46.077553  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.056s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25029,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.078184  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=2.188937
I20260812 06:18:46.096939  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.097657  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:46.208771  5811 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.045s	user 1.815s	sys 0.171s
I20260812 06:18:46.244531  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.147s	user 0.099s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":10281,"lbm_reads_lt_1ms":560,"lbm_write_time_us":30018,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:46.245270  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=10.126437
I20260812 06:18:46.273289  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: FlushDeltaMemStoresOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.028s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13082,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.273995  5985 maintenance_manager.cc:419] P c6df05db5d434c4dacc329618cbb9abe: Scheduling MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d): perf score=1.000000
I20260812 06:18:46.310031  5811 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.101s	user 0.002s	sys 0.000s
I20260812 06:18:46.310789  5811 tablet_server.cc:179] TabletServer@127.5.172.193:0 shutting down...
I20260812 06:18:46.395907  5921 maintenance_manager.cc:643] P c6df05db5d434c4dacc329618cbb9abe: MajorDeltaCompactionOp(25357abc5ac1468ea2fefde4b0f3f86d) complete. Timing: real 0.122s	user 0.088s	sys 0.030s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":859,"lbm_read_time_us":11857,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22474,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":102,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.396636  5811 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.397068  5811 tablet_replica.cc:333] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe: stopping tablet replica
I20260812 06:18:46.397331  5811 raft_consensus.cc:2243] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.397578  5811 raft_consensus.cc:2272] T 25357abc5ac1468ea2fefde4b0f3f86d P c6df05db5d434c4dacc329618cbb9abe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.413789  5811 tablet_server.cc:196] TabletServer@127.5.172.193:0 shutdown complete.
I20260812 06:18:46.429497  5811 master.cc:562] Master@127.5.172.254:36363 shutting down...
I20260812 06:18:46.433877  5811 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.434118  5811 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.434214  5811 tablet_replica.cc:333] T 00000000000000000000000000000000 P a0cb633a1dca4a18aa4a4be11ea2a56c: stopping tablet replica
I20260812 06:18:46.446900  5811 master.cc:584] Master@127.5.172.254:36363 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5689 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:46.536885  5811 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.172.254:43805
I20260812 06:18:46.537245  5811 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:46.539649  5811 server_base.cc:1061] running on GCE node
W20260812 06:18:46.539804  6018 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:46.539903  6016 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:46.539943  6020 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:46.540195  5811 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.540239  5811 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:46.540256  5811 hybrid_clock.cc:648] HybridClock initialized: now 1786515526540255 us; error 0 us; skew 500 ppm
I20260812 06:18:46.541157  5811 webserver.cc:533] Webserver started at http://127.5.172.254:40301/ using document root <none> and password file <none>
I20260812 06:18:46.541352  5811 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.541421  5811 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.541522  5811 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.541920  5811 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/master-0-root/instance:
uuid: "f42ae12bff514b3ea1fd3ce65643713f"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-zpfg"
I20260812 06:18:46.543579  5811 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:46.544637  6025 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:46.544953  5811 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.545049  5811 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/master-0-root
uuid: "f42ae12bff514b3ea1fd3ce65643713f"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-zpfg"
I20260812 06:18:46.545140  5811 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-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:46.580911  5811 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.581406  5811 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.585991  5811 rpc_server.cc:307] RPC server started. Bound to: 127.5.172.254:43805
I20260812 06:18:46.588763  6081 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.172.254:43805 every 8 connection(s)
I20260812 06:18:46.589010  6082 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:46.600400  6082 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f: Bootstrap starting.
I20260812 06:18:46.601432  6082 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.602708  6082 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f: No bootstrap required, opened a new log
I20260812 06:18:46.603178  6082 raft_consensus.cc:359] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER }
I20260812 06:18:46.603302  6082 raft_consensus.cc:385] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.603358  6082 raft_consensus.cc:740] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f42ae12bff514b3ea1fd3ce65643713f, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.603533  6082 consensus_queue.cc:260] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [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: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER }
I20260812 06:18:46.603637  6082 raft_consensus.cc:399] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.603693  6082 raft_consensus.cc:493] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.603756  6082 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.604615  6082 raft_consensus.cc:515] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER }
I20260812 06:18:46.604781  6082 leader_election.cc:304] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [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: f42ae12bff514b3ea1fd3ce65643713f; no voters: 
I20260812 06:18:46.605031  6082 leader_election.cc:290] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.605260  6086 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.605500  6086 raft_consensus.cc:697] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 1 LEADER]: Becoming Leader. State: Replica: f42ae12bff514b3ea1fd3ce65643713f, State: Running, Role: LEADER
I20260812 06:18:46.605640  6086 consensus_queue.cc:237] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [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: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER }
I20260812 06:18:46.605759  6082 sys_catalog.cc:565] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:46.606122  6087 sys_catalog.cc:455] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f42ae12bff514b3ea1fd3ce65643713f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER } }
I20260812 06:18:46.606236  6087 sys_catalog.cc:458] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.606374  6088 sys_catalog.cc:455] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [sys.catalog]: SysCatalogTable state changed. Reason: New leader f42ae12bff514b3ea1fd3ce65643713f. Latest consensus state: current_term: 1 leader_uuid: "f42ae12bff514b3ea1fd3ce65643713f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f42ae12bff514b3ea1fd3ce65643713f" member_type: VOTER } }
I20260812 06:18:46.606508  6088 sys_catalog.cc:458] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.606705  6090 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:46.607709  6090 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:46.608384  5811 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:46.609637  6090 catalog_manager.cc:1383] Generated new cluster ID: 2307035693cb40ed959bb3808ab74ea6
I20260812 06:18:46.609681  6090 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:46.640005  6090 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:46.640620  6090 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:46.649201  6090 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f: Generated new TSK 0
I20260812 06:18:46.649418  6090 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:46.673116  5811 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.675359  6104 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:46.675577  6105 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:46.675601  5811 server_base.cc:1061] running on GCE node
W20260812 06:18:46.675595  6107 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:46.675963  5811 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.676012  5811 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:46.676029  5811 hybrid_clock.cc:648] HybridClock initialized: now 1786515526676029 us; error 0 us; skew 500 ppm
I20260812 06:18:46.677063  5811 webserver.cc:533] Webserver started at http://127.5.172.193:38249/ using document root <none> and password file <none>
I20260812 06:18:46.677322  5811 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.677378  5811 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.677484  5811 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.677908  5811 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/instance:
uuid: "abab28c414df479a9a52d323904ad6e5"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-zpfg"
I20260812 06:18:46.679505  5811 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:46.680537  6113 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:46.680816  5811 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:46.680907  5811 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root
uuid: "abab28c414df479a9a52d323904ad6e5"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-zpfg"
I20260812 06:18:46.680997  5811 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-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:46.696362  5811 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.696815  5811 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.697188  5811 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:46.697696  5811 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:46.697758  5811 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.697822  5811 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:46.697856  5811 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.702580  5811 rpc_server.cc:307] RPC server started. Bound to: 127.5.172.193:34889
I20260812 06:18:46.702647  6179 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.172.193:34889 every 8 connection(s)
I20260812 06:18:46.707767  6180 heartbeater.cc:344] Connected to a master server at 127.5.172.254:43805
I20260812 06:18:46.707875  6180 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:46.708190  6180 heartbeater.cc:507] Master 127.5.172.254:43805 requested a full tablet report, sending...
I20260812 06:18:46.708889  6044 ts_manager.cc:194] Registered new tserver with Master: abab28c414df479a9a52d323904ad6e5 (127.5.172.193:34889)
I20260812 06:18:46.709621  6044 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51540
I20260812 06:18:46.709753  5811 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006681154s
I20260812 06:18:46.716756  6044 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51552:
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:46.726075  6142 tablet_service.cc:1511] Processing CreateTablet for tablet f31fa0058d084864aa608583ac70b962 (DEFAULT_TABLE table=heavy-update-compaction-test [id=db13ae2c315d4abdaa6cec5a673adb5d]), partition=
I20260812 06:18:46.726476  6142 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f31fa0058d084864aa608583ac70b962. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:46.728911  6193 tablet_bootstrap.cc:492] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Bootstrap starting.
I20260812 06:18:46.729802  6193 tablet_bootstrap.cc:654] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.731019  6193 tablet_bootstrap.cc:492] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: No bootstrap required, opened a new log
I20260812 06:18:46.731155  6193 ts_tablet_manager.cc:1403] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:46.731679  6193 raft_consensus.cc:359] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abab28c414df479a9a52d323904ad6e5" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 34889 } }
I20260812 06:18:46.731771  6193 raft_consensus.cc:385] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.731794  6193 raft_consensus.cc:740] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: abab28c414df479a9a52d323904ad6e5, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.731951  6193 consensus_queue.cc:260] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [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: "abab28c414df479a9a52d323904ad6e5" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 34889 } }
I20260812 06:18:46.732028  6193 raft_consensus.cc:399] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.732052  6193 raft_consensus.cc:493] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.732088  6193 raft_consensus.cc:3060] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.732795  6193 raft_consensus.cc:515] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abab28c414df479a9a52d323904ad6e5" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 34889 } }
I20260812 06:18:46.732918  6193 leader_election.cc:304] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [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: abab28c414df479a9a52d323904ad6e5; no voters: 
I20260812 06:18:46.733093  6193 leader_election.cc:290] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.733229  6195 raft_consensus.cc:2804] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.733454  6195 raft_consensus.cc:697] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 1 LEADER]: Becoming Leader. State: Replica: abab28c414df479a9a52d323904ad6e5, State: Running, Role: LEADER
I20260812 06:18:46.733479  6193 ts_tablet_manager.cc:1434] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:46.733500  6180 heartbeater.cc:499] Master 127.5.172.254:43805 was elected leader, sending a full tablet report...
I20260812 06:18:46.733665  6195 consensus_queue.cc:237] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [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: "abab28c414df479a9a52d323904ad6e5" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 34889 } }
I20260812 06:18:46.734988  6044 catalog_manager.cc:5719] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 reported cstate change: term changed from 0 to 1, leader changed from <none> to abab28c414df479a9a52d323904ad6e5 (127.5.172.193). New cstate: current_term: 1 leader_uuid: "abab28c414df479a9a52d323904ad6e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "abab28c414df479a9a52d323904ad6e5" member_type: VOTER last_known_addr { host: "127.5.172.193" port: 34889 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:46.797760  5811 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.007s
I20260812 06:18:46.953611  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushMRSOp(f31fa0058d084864aa608583ac70b962): perf score=19.054940
I20260812 06:18:47.097695  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushMRSOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.144s	user 0.103s	sys 0.036s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1015,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36290,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:47.098407  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 20743880 bytes of WAL
I20260812 06:18:47.098658  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 2 log segments from log reader
I20260812 06:18:47.098702  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000001 (ops 1-6)
I20260812 06:18:47.098732  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000002 (ops 7-11)
I20260812 06:18:47.103040  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:47.103376  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:47.117442  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.117974  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962): 16411392 bytes on disk
I20260812 06:18:47.118553  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":137,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.118992  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:47.263659  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.145s	user 0.105s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":451,"lbm_read_time_us":10478,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26736,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":346,"threads_started":5,"update_count":2000}
I20260812 06:18:47.264334  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:47.311079  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.047s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16163,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.311591  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:47.322238  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.322978  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:47.453084  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.130s	user 0.073s	sys 0.056s 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":1195,"lbm_read_time_us":9518,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25666,"lbm_writes_lt_1ms":443,"mutex_wait_us":415,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:18:47.453789  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:47.505978  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.052s	user 0.028s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17888,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.506626  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:47.517886  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.518450  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:47.673386  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.155s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":444,"lbm_read_time_us":11432,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23650,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:18:47.674042  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:47.718834  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.045s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14075,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.719319  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:47.730967  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.731555  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:47.860249  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.128s	user 0.094s	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":1016,"lbm_read_time_us":8352,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23465,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":71936,"update_count":2000}
I20260812 06:18:47.861229  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:47.898828  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14446,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.899634  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:47.914951  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.915588  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:48.038733  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.123s	user 0.098s	sys 0.024s 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":2387,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23347,"lbm_writes_lt_1ms":443,"mutex_wait_us":620,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:48.039338  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:48.094906  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.055s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15312,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.095594  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:48.107795  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.108392  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:48.277354  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.169s	user 0.107s	sys 0.057s 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":261,"lbm_read_time_us":13320,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26590,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:18:48.278014  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=11.118625
I20260812 06:18:48.310907  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13430,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.311478  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:48.326156  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4708,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.326792  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushMRSOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:48.391037  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushMRSOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.064s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1972,"drs_written":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2355,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:48.391875  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 108535449 bytes of WAL
I20260812 06:18:48.392190  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 11 log segments from log reader
I20260812 06:18:48.392256  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000003 (ops 12-16)
I20260812 06:18:48.392299  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000004 (ops 17-21)
I20260812 06:18:48.392323  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000005 (ops 22-26)
I20260812 06:18:48.392345  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000006 (ops 27-30)
I20260812 06:18:48.392369  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000007 (ops 31-35)
I20260812 06:18:48.392405  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000008 (ops 36-40)
I20260812 06:18:48.392431  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000009 (ops 41-44)
I20260812 06:18:48.392463  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000010 (ops 45-49)
I20260812 06:18:48.392485  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000011 (ops 50-54)
I20260812 06:18:48.392513  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000012 (ops 55-59)
I20260812 06:18:48.392545  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000013 (ops 60-64)
I20260812 06:18:48.420104  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:48.422643  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962): 463 bytes on disk
I20260812 06:18:48.423087  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.423566  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=6.157687
I20260812 06:18:48.459126  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.035s	user 0.020s	sys 0.008s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":11748,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:48.459676  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 11564875 bytes of WAL
I20260812 06:18:48.459897  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 1 log segments from log reader
I20260812 06:18:48.459940  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000014 (ops 65-68)
I20260812 06:18:48.462059  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:48.462447  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:48.475129  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.475685  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:48.718803  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.243s	user 0.143s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":453,"lbm_read_time_us":16311,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39968,"lbm_writes_lt_1ms":743,"mutex_wait_us":108,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:18:48.719800  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=16.079562
I20260812 06:18:48.771204  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.051s	user 0.021s	sys 0.029s Metrics: {"bytes_written":17968822,"delete_count":0,"lbm_write_time_us":22722,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:18:48.771742  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=1.196750
I20260812 06:18:48.796877  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.025s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:48.797413  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:48.807694  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3766,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.808288  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:49.016247  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.208s	user 0.108s	sys 0.095s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877186,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1474,"lbm_read_time_us":13341,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32096,"lbm_writes_lt_1ms":643,"mutex_wait_us":442,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":250880,"update_count":3000}
I20260812 06:18:49.017089  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=16.079562
I20260812 06:18:49.084872  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.068s	user 0.032s	sys 0.023s Metrics: {"bytes_written":17845750,"delete_count":0,"lbm_write_time_us":26599,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2175}
I20260812 06:18:49.085337  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=5.165500
I20260812 06:18:49.104496  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":6769240,"delete_count":0,"lbm_write_time_us":7609,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:18:49.105051  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:49.308969  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.204s	user 0.138s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877112,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":442,"lbm_read_time_us":14044,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35445,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:18:49.309885  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=16.079562
I20260812 06:18:49.363289  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.053s	user 0.015s	sys 0.032s Metrics: {"bytes_written":17968821,"delete_count":0,"lbm_write_time_us":20991,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:18:49.363791  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=1.196750
I20260812 06:18:49.375568  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.012s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":3097,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:49.376037  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:49.386168  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.386839  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:49.597265  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.210s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877185,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1229,"lbm_read_time_us":14689,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35390,"lbm_writes_lt_1ms":643,"mutex_wait_us":489,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":3000}
I20260812 06:18:49.597841  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=14.095187
I20260812 06:18:49.652457  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.054s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23108,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.652989  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:49.663754  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.664206  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:49.841625  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.177s	user 0.118s	sys 0.056s 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":1048,"lbm_read_time_us":10930,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30330,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:49.842383  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=14.095187
I20260812 06:18:49.901268  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.059s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19611,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.901870  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:49.914209  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.914873  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushMRSOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:49.950519  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushMRSOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.035s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1483,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1452,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:49.951272  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 124710321 bytes of WAL
I20260812 06:18:49.951516  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 12 log segments from log reader
I20260812 06:18:49.951583  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000015 (ops 69-73)
I20260812 06:18:49.951634  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000016 (ops 74-78)
I20260812 06:18:49.951694  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000017 (ops 79-83)
I20260812 06:18:49.951736  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000018 (ops 84-88)
I20260812 06:18:49.951773  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000019 (ops 89-93)
I20260812 06:18:49.951814  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000020 (ops 94-98)
I20260812 06:18:49.951860  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000021 (ops 99-103)
I20260812 06:18:49.951900  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000022 (ops 104-108)
I20260812 06:18:49.951939  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000023 (ops 109-113)
I20260812 06:18:49.951980  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000024 (ops 114-118)
I20260812 06:18:49.952020  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000025 (ops 119-123)
I20260812 06:18:49.952061  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000026 (ops 124-128)
I20260812 06:18:49.978214  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:49.978683  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962): 472 bytes on disk
I20260812 06:18:49.979151  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.979681  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=3.181125
I20260812 06:18:50.003607  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.024s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6571,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.004151  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:50.014715  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.015252  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:50.243892  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.228s	user 0.153s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":447,"lbm_read_time_us":15642,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39293,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23424,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:50.245276  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=18.063937
I20260812 06:18:50.308014  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.062s	user 0.026s	sys 0.027s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24963,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:50.308580  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:50.320792  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.321306  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:50.480599  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.159s	user 0.138s	sys 0.021s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":11890,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31112,"lbm_writes_lt_1ms":643,"mutex_wait_us":117,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:50.481357  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=14.095187
I20260812 06:18:50.521867  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17952,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.522524  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:50.543771  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.019s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.544245  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:50.692337  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.148s	user 0.106s	sys 0.036s 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":835,"lbm_read_time_us":8831,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26864,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:50.693173  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=14.095187
I20260812 06:18:50.748584  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.055s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24295,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.749161  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:50.893107  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.144s	user 0.113s	sys 0.027s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":558,"lbm_read_time_us":11244,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22226,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.893648  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=11.118625
I20260812 06:18:50.927990  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.033s	user 0.007s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14854,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:50.928802  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:50.962929  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.034s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6145,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.963531  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:50.978996  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.015s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.979656  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:51.170559  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.191s	user 0.128s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":901,"lbm_read_time_us":10963,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31751,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:51.171455  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=14.095187
I20260812 06:18:51.218475  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.047s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20725,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.219040  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:51.233697  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.234253  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:51.386238  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.152s	user 0.107s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":11016,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29607,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:51.386916  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=11.118625
I20260812 06:18:51.425675  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.039s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16669,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:51.426282  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:51.447835  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.021s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.448522  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushMRSOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:51.499470  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushMRSOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.051s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1532,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1902,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:51.500262  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 121006692 bytes of WAL
I20260812 06:18:51.500521  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 12 log segments from log reader
I20260812 06:18:51.500568  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000027 (ops 129-133)
I20260812 06:18:51.500598  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000028 (ops 134-138)
I20260812 06:18:51.500664  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000029 (ops 139-143)
I20260812 06:18:51.500723  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000030 (ops 144-148)
I20260812 06:18:51.500770  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000031 (ops 149-153)
I20260812 06:18:51.500825  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000032 (ops 154-158)
I20260812 06:18:51.500872  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000033 (ops 159-162)
I20260812 06:18:51.500911  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000034 (ops 163-167)
I20260812 06:18:51.500948  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000035 (ops 168-172)
I20260812 06:18:51.500990  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000036 (ops 173-177)
I20260812 06:18:51.501029  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000037 (ops 178-182)
I20260812 06:18:51.501068  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000038 (ops 183-187)
I20260812 06:18:51.527434  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:51.527935  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962): 493 bytes on disk
I20260812 06:18:51.528755  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: UndoDeltaBlockGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.529583  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=6.157687
I20260812 06:18:51.568390  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.039s	user 0.010s	sys 0.027s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12113,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:51.569141  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling LogGCOp(f31fa0058d084864aa608583ac70b962): free 12017952 bytes of WAL
I20260812 06:18:51.569470  6118 log_reader.cc:385] T f31fa0058d084864aa608583ac70b962: removed 1 log segments from log reader
I20260812 06:18:51.569551  6118 log.cc:1079] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: Deleting log segment in path: /tmp/dist-test-tasktfJD69/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520836403-5811-0/minicluster-data/ts-0-root/wals/f31fa0058d084864aa608583ac70b962/wal-000000039 (ops 188-192)
I20260812 06:18:51.571976  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: LogGCOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:51.572369  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=2.188937
I20260812 06:18:51.584411  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.585031  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962): perf score=1.000000
I20260812 06:18:51.740899  5811 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.943s	user 1.856s	sys 0.157s
I20260812 06:18:51.802737  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: MajorDeltaCompactionOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.217s	user 0.130s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979744,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15551,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37864,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3500}
I20260812 06:18:51.803272  6181 maintenance_manager.cc:419] P abab28c414df479a9a52d323904ad6e5: Scheduling FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962): perf score=10.126437
I20260812 06:18:51.822542  5811 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.003s	sys 0.000s
I20260812 06:18:51.823082  5811 tablet_server.cc:179] TabletServer@127.5.172.193:0 shutting down...
I20260812 06:18:51.841729  6118 maintenance_manager.cc:643] P abab28c414df479a9a52d323904ad6e5: FlushDeltaMemStoresOp(f31fa0058d084864aa608583ac70b962) complete. Timing: real 0.038s	user 0.012s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17586,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.842303  5811 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:51.842571  5811 tablet_replica.cc:333] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5: stopping tablet replica
I20260812 06:18:51.842722  5811 raft_consensus.cc:2243] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.853372  5811 raft_consensus.cc:2272] T f31fa0058d084864aa608583ac70b962 P abab28c414df479a9a52d323904ad6e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.867960  5811 tablet_server.cc:196] TabletServer@127.5.172.193:0 shutdown complete.
I20260812 06:18:51.871075  5811 master.cc:562] Master@127.5.172.254:43805 shutting down...
I20260812 06:18:51.874145  5811 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.874305  5811 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.874418  5811 tablet_replica.cc:333] T 00000000000000000000000000000000 P f42ae12bff514b3ea1fd3ce65643713f: stopping tablet replica
I20260812 06:18:51.886778  5811 master.cc:584] Master@127.5.172.254:43805 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5434 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11124 ms total)

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