[==========] 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:27.353487  4041 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.242.126:46193
I20260812 06:18:27.354401  4041 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:27.354949  4041 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.360559  4062 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:27.360574  4059 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:27.360795  4057 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:27.360802  4041 server_base.cc:1061] running on GCE node
I20260812 06:18:27.361330  4041 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.361425  4041 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:27.361459  4041 hybrid_clock.cc:648] HybridClock initialized: now 1786515507361457 us; error 0 us; skew 500 ppm
I20260812 06:18:27.363018  4041 webserver.cc:533] Webserver started at http://127.3.242.126:37335/ using document root <none> and password file <none>
I20260812 06:18:27.363498  4041 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.363559  4041 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.363745  4041 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.365337  4041 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/master-0-root/instance:
uuid: "a094a6afaa17415b86d659dccf0ef1b7"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-266d"
I20260812 06:18:27.368620  4041 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.370548  4073 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:27.371474  4041 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:18:27.371582  4041 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/master-0-root
uuid: "a094a6afaa17415b86d659dccf0ef1b7"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-266d"
I20260812 06:18:27.371675  4041 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-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:27.391623  4041 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.392201  4041 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:27.392359  4041 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.399765  4169 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.242.126:46193 every 8 connection(s)
I20260812 06:18:27.399767  4041 rpc_server.cc:307] RPC server started. Bound to: 127.3.242.126:46193
I20260812 06:18:27.401898  4170 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:27.406900  4170 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: Bootstrap starting.
I20260812 06:18:27.409060  4170 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.409902  4170 log.cc:826] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.411396  4170 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: No bootstrap required, opened a new log
I20260812 06:18:27.413980  4170 raft_consensus.cc:359] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER }
I20260812 06:18:27.414131  4170 raft_consensus.cc:385] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.414183  4170 raft_consensus.cc:740] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a094a6afaa17415b86d659dccf0ef1b7, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.414726  4170 consensus_queue.cc:260] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [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: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER }
I20260812 06:18:27.414865  4170 raft_consensus.cc:399] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.414908  4170 raft_consensus.cc:493] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.414990  4170 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.415663  4170 raft_consensus.cc:515] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER }
I20260812 06:18:27.416021  4170 leader_election.cc:304] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [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: a094a6afaa17415b86d659dccf0ef1b7; no voters: 
I20260812 06:18:27.416254  4170 leader_election.cc:290] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.416396  4175 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.416606  4175 raft_consensus.cc:697] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 1 LEADER]: Becoming Leader. State: Replica: a094a6afaa17415b86d659dccf0ef1b7, State: Running, Role: LEADER
I20260812 06:18:27.417006  4175 consensus_queue.cc:237] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [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: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER }
I20260812 06:18:27.417121  4170 sys_catalog.cc:565] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.418850  4178 sys_catalog.cc:455] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a094a6afaa17415b86d659dccf0ef1b7. Latest consensus state: current_term: 1 leader_uuid: "a094a6afaa17415b86d659dccf0ef1b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER } }
I20260812 06:18:27.418866  4176 sys_catalog.cc:455] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a094a6afaa17415b86d659dccf0ef1b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a094a6afaa17415b86d659dccf0ef1b7" member_type: VOTER } }
I20260812 06:18:27.418972  4178 sys_catalog.cc:458] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.418973  4176 sys_catalog.cc:458] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.419361  4201 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.419495  4041 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:27.421499  4201 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.425942  4201 catalog_manager.cc:1383] Generated new cluster ID: 20b0343cd07a4e24a0236e0cfb89e2b2
I20260812 06:18:27.425992  4201 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.435962  4201 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.436698  4201 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.442014  4201 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: Generated new TSK 0
I20260812 06:18:27.442476  4201 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.452322  4041 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.455104  4214 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:27.455183  4218 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:27.455382  4212 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:27.455399  4041 server_base.cc:1061] running on GCE node
I20260812 06:18:27.455607  4041 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.455657  4041 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:27.455678  4041 hybrid_clock.cc:648] HybridClock initialized: now 1786515507455678 us; error 0 us; skew 500 ppm
I20260812 06:18:27.456599  4041 webserver.cc:533] Webserver started at http://127.3.242.65:39841/ using document root <none> and password file <none>
I20260812 06:18:27.456758  4041 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.456811  4041 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.456883  4041 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.457329  4041 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/instance:
uuid: "685dfd1a8c4c42e18814bf29325b7247"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-266d"
I20260812 06:18:27.459059  4041 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:27.460103  4224 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:27.460327  4041 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:27.460383  4041 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root
uuid: "685dfd1a8c4c42e18814bf29325b7247"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-266d"
I20260812 06:18:27.460446  4041 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-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:27.511812  4041 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.512269  4041 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.512746  4041 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.513687  4041 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.513751  4041 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.513806  4041 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.513841  4041 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.520515  4041 rpc_server.cc:307] RPC server started. Bound to: 127.3.242.65:35855
I20260812 06:18:27.520570  4338 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.242.65:35855 every 8 connection(s)
I20260812 06:18:27.533370  4339 heartbeater.cc:344] Connected to a master server at 127.3.242.126:46193
I20260812 06:18:27.533625  4339 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.534086  4339 heartbeater.cc:507] Master 127.3.242.126:46193 requested a full tablet report, sending...
I20260812 06:18:27.535487  4111 ts_manager.cc:194] Registered new tserver with Master: 685dfd1a8c4c42e18814bf29325b7247 (127.3.242.65:35855)
I20260812 06:18:27.535563  4041 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014392845s
I20260812 06:18:27.537014  4111 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42974
I20260812 06:18:27.544987  4111 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42988:
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:27.558568  4266 tablet_service.cc:1511] Processing CreateTablet for tablet 907c1a4b2ca54891b008bcb774b55ff2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=358004bf7cae4352afa9ce3bff255631]), partition=
I20260812 06:18:27.558991  4266 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 907c1a4b2ca54891b008bcb774b55ff2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.560988  4360 tablet_bootstrap.cc:492] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Bootstrap starting.
I20260812 06:18:27.562311  4360 tablet_bootstrap.cc:654] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.563367  4360 tablet_bootstrap.cc:492] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: No bootstrap required, opened a new log
I20260812 06:18:27.563458  4360 ts_tablet_manager.cc:1403] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.563859  4360 raft_consensus.cc:359] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "685dfd1a8c4c42e18814bf29325b7247" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 35855 } }
I20260812 06:18:27.563953  4360 raft_consensus.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.563985  4360 raft_consensus.cc:740] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 685dfd1a8c4c42e18814bf29325b7247, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.564103  4360 consensus_queue.cc:260] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [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: "685dfd1a8c4c42e18814bf29325b7247" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 35855 } }
I20260812 06:18:27.564169  4360 raft_consensus.cc:399] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.564210  4360 raft_consensus.cc:493] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.564258  4360 raft_consensus.cc:3060] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.564911  4360 raft_consensus.cc:515] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "685dfd1a8c4c42e18814bf29325b7247" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 35855 } }
I20260812 06:18:27.565063  4360 leader_election.cc:304] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [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: 685dfd1a8c4c42e18814bf29325b7247; no voters: 
I20260812 06:18:27.565270  4360 leader_election.cc:290] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.565828  4363 raft_consensus.cc:2804] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.566354  4363 raft_consensus.cc:697] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 1 LEADER]: Becoming Leader. State: Replica: 685dfd1a8c4c42e18814bf29325b7247, State: Running, Role: LEADER
I20260812 06:18:27.566390  4339 heartbeater.cc:499] Master 127.3.242.126:46193 was elected leader, sending a full tablet report...
I20260812 06:18:27.566504  4363 consensus_queue.cc:237] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [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: "685dfd1a8c4c42e18814bf29325b7247" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 35855 } }
I20260812 06:18:27.566156  4360 ts_tablet_manager.cc:1434] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.568904  4111 catalog_manager.cc:5719] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 reported cstate change: term changed from 0 to 1, leader changed from <none> to 685dfd1a8c4c42e18814bf29325b7247 (127.3.242.65). New cstate: current_term: 1 leader_uuid: "685dfd1a8c4c42e18814bf29325b7247" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "685dfd1a8c4c42e18814bf29325b7247" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 35855 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.626104  4041 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.016s	sys 0.007s
I20260812 06:18:27.771631  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=19.054940
I20260812 06:18:27.926456  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.154s	user 0.103s	sys 0.041s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":307,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":795,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37679,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":187,"threads_started":1,"update_count":1450}
I20260812 06:18:27.927376  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling LogGCOp(907c1a4b2ca54891b008bcb774b55ff2): free 20290830 bytes of WAL
I20260812 06:18:27.927634  4233 log_reader.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2: removed 2 log segments from log reader
I20260812 06:18:27.927690  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000001 (ops 1-6)
I20260812 06:18:27.927747  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000002 (ops 7-10)
I20260812 06:18:27.931241  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: LogGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:27.931509  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:27.943933  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.944890  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.086540  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.141s	user 0.099s	sys 0.039s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303031,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":8710,"lbm_reads_lt_1ms":454,"lbm_write_time_us":23195,"lbm_writes_lt_1ms":433,"mutex_wait_us":2,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":281,"threads_started":5,"update_count":1950}
I20260812 06:18:28.087059  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.119719  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13163,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.120163  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2): 16821647 bytes on disk
I20260812 06:18:28.120649  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2) 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:28.121032  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.136015  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.136585  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.257782  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":8307,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23647,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:18:28.258273  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.299347  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.041s	user 0.006s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13946,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.299757  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.309223  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.309710  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.423694  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.114s	user 0.094s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":8400,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21176,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:28.424197  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.469249  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.045s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14846,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.469801  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.479740  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.480202  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.613242  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.133s	user 0.080s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1531,"lbm_read_time_us":10991,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20673,"lbm_writes_lt_1ms":443,"mutex_wait_us":480,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:28.613710  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.647753  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.034s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14634,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.648226  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.658690  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.659343  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.772423  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.113s	user 0.089s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":43,"lbm_read_time_us":8034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20268,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:18:28.772990  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.803208  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.030s	user 0.022s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12231,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.803627  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.813939  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.814463  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:28.929476  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.115s	user 0.100s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":8532,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20727,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:28.929951  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:28.969408  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.039s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15559,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.969871  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:28.979501  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.979965  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:29.092491  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.112s	user 0.102s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":7081,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20941,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:29.093070  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=10.126437
I20260812 06:18:29.138669  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.045s	user 0.014s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14317,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.139210  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.154011  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.154470  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:29.198196  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.044s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":142,"dirs.run_wall_time_us":1212,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1981,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:29.199066  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling LogGCOp(907c1a4b2ca54891b008bcb774b55ff2): free 133024358 bytes of WAL
I20260812 06:18:29.199298  4233 log_reader.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2: removed 13 log segments from log reader
I20260812 06:18:29.199350  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000003 (ops 11-15)
I20260812 06:18:29.199384  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000004 (ops 16-20)
I20260812 06:18:29.199424  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000005 (ops 21-25)
I20260812 06:18:29.199455  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000006 (ops 26-30)
I20260812 06:18:29.199491  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000007 (ops 31-34)
I20260812 06:18:29.199528  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000008 (ops 35-39)
I20260812 06:18:29.199566  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000009 (ops 40-44)
I20260812 06:18:29.199605  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000010 (ops 45-49)
I20260812 06:18:29.199643  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000011 (ops 50-54)
I20260812 06:18:29.199682  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000012 (ops 55-59)
I20260812 06:18:29.199720  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000013 (ops 60-64)
I20260812 06:18:29.199759  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000014 (ops 65-69)
I20260812 06:18:29.199796  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000015 (ops 70-74)
I20260812 06:18:29.221784  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: LogGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:29.222218  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.240109  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.018s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.240566  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.250257  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.250808  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:29.435978  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.185s	user 0.109s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":190,"lbm_read_time_us":11725,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32718,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":32256,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:18:29.436569  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2): 482 bytes on disk
I20260812 06:18:29.437019  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2) 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:29.437592  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:29.487615  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.488107  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:29.624734  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.136s	user 0.078s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":199,"lbm_read_time_us":7921,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22606,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:18:29.625334  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=11.118625
I20260812 06:18:29.666931  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.041s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18777,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.667438  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.682814  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.683314  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.695761  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.696161  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:29.877421  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.181s	user 0.102s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":335,"lbm_read_time_us":10014,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28737,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:29.877938  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:29.921991  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.044s	user 0.029s	sys 0.009s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.922502  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:29.932061  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.932520  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:30.093425  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.161s	user 0.120s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":822,"lbm_read_time_us":9036,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31608,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:30.093936  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:30.141672  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.048s	user 0.041s	sys 0.005s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20047,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.142184  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:30.156874  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.157410  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:30.311622  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.154s	user 0.120s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":9846,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28372,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:18:30.312608  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:30.364214  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.051s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24071,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.364868  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:30.388468  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.388945  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:30.399653  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.400251  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:30.558852  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.158s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":616,"lbm_read_time_us":11231,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32476,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:30.559523  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:30.598876  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17508,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.599617  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:30.615851  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.616320  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:30.676702  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.060s	user 0.030s	sys 0.011s Metrics: {"bytes_written":1357578,"cfile_init":1,"dirs.queue_time_us":36,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2243,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33,"spinlock_wait_cycles":16128}
I20260812 06:18:30.677594  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling LogGCOp(907c1a4b2ca54891b008bcb774b55ff2): free 125616671 bytes of WAL
I20260812 06:18:30.677829  4233 log_reader.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2: removed 13 log segments from log reader
I20260812 06:18:30.677881  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000016 (ops 75-79)
I20260812 06:18:30.677922  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000017 (ops 80-84)
I20260812 06:18:30.677954  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000018 (ops 85-89)
I20260812 06:18:30.677981  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000019 (ops 90-94)
I20260812 06:18:30.678012  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000020 (ops 95-98)
I20260812 06:18:30.678040  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000021 (ops 99-103)
I20260812 06:18:30.678066  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000022 (ops 104-108)
I20260812 06:18:30.678092  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000023 (ops 109-112)
I20260812 06:18:30.678122  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000024 (ops 113-117)
I20260812 06:18:30.678148  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000025 (ops 118-122)
I20260812 06:18:30.678179  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000026 (ops 123-126)
I20260812 06:18:30.678210  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000027 (ops 127-131)
I20260812 06:18:30.678241  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000028 (ops 132-136)
I20260812 06:18:30.698895  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: LogGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:30.699285  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=6.157687
I20260812 06:18:30.731596  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.032s	user 0.011s	sys 0.007s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":8436,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:30.732120  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling LogGCOp(907c1a4b2ca54891b008bcb774b55ff2): free 11564893 bytes of WAL
I20260812 06:18:30.732321  4233 log_reader.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2: removed 1 log segments from log reader
I20260812 06:18:30.732368  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000029 (ops 137-140)
I20260812 06:18:30.734225  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: LogGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:30.734535  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2): 507 bytes on disk
I20260812 06:18:30.734915  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.735474  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:30.745915  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.746346  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:30.980635  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.234s	user 0.149s	sys 0.085s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123162,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":577,"lbm_read_time_us":16439,"lbm_reads_lt_1ms":874,"lbm_write_time_us":37366,"lbm_writes_lt_1ms":843,"mutex_wait_us":39,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14464,"thread_start_us":85,"threads_started":1,"update_count":4000}
I20260812 06:18:30.981207  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=18.063937
I20260812 06:18:31.034399  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.053s	user 0.020s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":22890,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.034849  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:31.191437  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.156s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815567,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":167,"lbm_read_time_us":12212,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25431,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:18:31.191908  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=14.095187
I20260812 06:18:31.243150  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.051s	user 0.011s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16959,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.243695  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:31.253526  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.254019  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:31.418678  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.164s	user 0.098s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":11519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27049,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.419368  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=11.118625
I20260812 06:18:31.453622  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.034s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14036,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.454164  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:31.466743  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.467213  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:31.611021  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.144s	user 0.096s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":92,"lbm_read_time_us":8364,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22174,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.611572  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=11.118625
I20260812 06:18:31.646744  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.035s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15095,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.647315  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:31.667484  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.020s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.667908  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:31.677516  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.677922  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:31.819705  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.142s	user 0.113s	sys 0.023s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":152,"lbm_read_time_us":11502,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25041,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:31.820326  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=11.118625
I20260812 06:18:31.856792  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.036s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":15435,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.857304  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:31.871977  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.015s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.872641  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:31.991320  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.119s	user 0.113s	sys 0.003s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":915,"lbm_read_time_us":8430,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23572,"lbm_writes_lt_1ms":443,"mutex_wait_us":251,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.991852  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=11.118625
I20260812 06:18:32.031213  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.039s	user 0.010s	sys 0.027s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13334,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.031701  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=2.188937
I20260812 06:18:32.044858  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3381,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.045346  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:32.080039  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushMRSOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.035s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":638,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1404,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.080912  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling LogGCOp(907c1a4b2ca54891b008bcb774b55ff2): free 121006692 bytes of WAL
I20260812 06:18:32.081202  4233 log_reader.cc:385] T 907c1a4b2ca54891b008bcb774b55ff2: removed 12 log segments from log reader
I20260812 06:18:32.081254  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000030 (ops 141-145)
I20260812 06:18:32.081293  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000031 (ops 146-150)
I20260812 06:18:32.081326  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000032 (ops 151-155)
I20260812 06:18:32.081358  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000033 (ops 156-160)
I20260812 06:18:32.081389  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000034 (ops 161-165)
I20260812 06:18:32.081420  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000035 (ops 166-170)
I20260812 06:18:32.081450  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000036 (ops 171-175)
I20260812 06:18:32.081481  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000037 (ops 176-180)
I20260812 06:18:32.081512  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000038 (ops 181-185)
I20260812 06:18:32.081543  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000039 (ops 186-190)
I20260812 06:18:32.081589  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000040 (ops 191-194)
I20260812 06:18:32.081621  4233 log.cc:1079] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/907c1a4b2ca54891b008bcb774b55ff2/wal-000000041 (ops 195-199)
I20260812 06:18:32.100664  4041 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.474s	user 1.633s	sys 0.157s
I20260812 06:18:32.102771  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: LogGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.022s	user 0.002s	sys 0.018s Metrics: {}
I20260812 06:18:32.103127  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=6.157687
I20260812 06:18:32.119311  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: FlushDeltaMemStoresOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7000,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:32.119689  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2): 472 bytes on disk
I20260812 06:18:32.120039  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: UndoDeltaBlockGCOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.120514  4340 maintenance_manager.cc:419] P 685dfd1a8c4c42e18814bf29325b7247: Scheduling MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2): perf score=1.000000
I20260812 06:18:32.164299  4041 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.001s	sys 0.000s
I20260812 06:18:32.164887  4041 tablet_server.cc:179] TabletServer@127.3.242.65:0 shutting down...
I20260812 06:18:32.249343  4233 maintenance_manager.cc:643] P 685dfd1a8c4c42e18814bf29325b7247: MajorDeltaCompactionOp(907c1a4b2ca54891b008bcb774b55ff2) complete. Timing: real 0.129s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_hit":364,"cfile_cache_hit_bytes":14851460,"cfile_cache_miss":269,"cfile_cache_miss_bytes":14066747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":526,"lbm_read_time_us":5844,"lbm_reads_lt_1ms":301,"lbm_write_time_us":25514,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":145664,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:18:32.250406  4041 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:32.250777  4041 tablet_replica.cc:333] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247: stopping tablet replica
I20260812 06:18:32.250993  4041 raft_consensus.cc:2243] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.251219  4041 raft_consensus.cc:2272] T 907c1a4b2ca54891b008bcb774b55ff2 P 685dfd1a8c4c42e18814bf29325b7247 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.265880  4041 tablet_server.cc:196] TabletServer@127.3.242.65:0 shutdown complete.
I20260812 06:18:32.299674  4041 master.cc:562] Master@127.3.242.126:46193 shutting down...
I20260812 06:18:32.302835  4041 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:32.302984  4041 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:32.303037  4041 tablet_replica.cc:333] T 00000000000000000000000000000000 P a094a6afaa17415b86d659dccf0ef1b7: stopping tablet replica
I20260812 06:18:32.315044  4041 master.cc:584] Master@127.3.242.126:46193 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5031 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:32.392603  4041 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.242.126:35843
I20260812 06:18:32.392967  4041 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.394819  4392 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:32.394937  4395 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:32.395013  4041 server_base.cc:1061] running on GCE node
W20260812 06:18:32.395094  4393 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:32.395280  4041 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.395324  4041 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:32.395344  4041 hybrid_clock.cc:648] HybridClock initialized: now 1786515512395344 us; error 0 us; skew 500 ppm
I20260812 06:18:32.396162  4041 webserver.cc:533] Webserver started at http://127.3.242.126:36151/ using document root <none> and password file <none>
I20260812 06:18:32.396322  4041 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.396370  4041 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.396446  4041 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.396807  4041 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/master-0-root/instance:
uuid: "a457b5ff3435418ca3a3a5b2e0e20c14"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-266d"
I20260812 06:18:32.398252  4041 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:32.399071  4409 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.399266  4041 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:32.399336  4041 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/master-0-root
uuid: "a457b5ff3435418ca3a3a5b2e0e20c14"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-266d"
I20260812 06:18:32.399401  4041 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:32.413335  4041 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.413636  4041 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.417508  4041 rpc_server.cc:307] RPC server started. Bound to: 127.3.242.126:35843
I20260812 06:18:32.421219  4518 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.242.126:35843 every 8 connection(s)
I20260812 06:18:32.421690  4519 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.423344  4519 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14: Bootstrap starting.
I20260812 06:18:32.424079  4519 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.424970  4519 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14: No bootstrap required, opened a new log
I20260812 06:18:32.425333  4519 raft_consensus.cc:359] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER }
I20260812 06:18:32.425412  4519 raft_consensus.cc:385] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.425432  4519 raft_consensus.cc:740] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a457b5ff3435418ca3a3a5b2e0e20c14, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.425545  4519 consensus_queue.cc:260] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [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: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER }
I20260812 06:18:32.425628  4519 raft_consensus.cc:399] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.425658  4519 raft_consensus.cc:493] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.425693  4519 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.426317  4519 raft_consensus.cc:515] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER }
I20260812 06:18:32.426429  4519 leader_election.cc:304] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [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: a457b5ff3435418ca3a3a5b2e0e20c14; no voters: 
I20260812 06:18:32.426569  4519 leader_election.cc:290] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.426678  4529 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.426856  4529 raft_consensus.cc:697] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 1 LEADER]: Becoming Leader. State: Replica: a457b5ff3435418ca3a3a5b2e0e20c14, State: Running, Role: LEADER
I20260812 06:18:32.426988  4519 sys_catalog.cc:565] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:32.427016  4529 consensus_queue.cc:237] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [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: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER }
I20260812 06:18:32.427428  4531 sys_catalog.cc:455] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a457b5ff3435418ca3a3a5b2e0e20c14. Latest consensus state: current_term: 1 leader_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER } }
I20260812 06:18:32.427403  4530 sys_catalog.cc:455] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a457b5ff3435418ca3a3a5b2e0e20c14" member_type: VOTER } }
I20260812 06:18:32.427592  4530 sys_catalog.cc:458] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.427533  4531 sys_catalog.cc:458] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:32.427888  4538 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:32.428651  4538 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:32.428913  4041 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:32.430365  4538 catalog_manager.cc:1383] Generated new cluster ID: 2e15263789d14b9db85b7e3e80193de0
I20260812 06:18:32.430410  4538 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:32.445328  4538 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:32.445818  4538 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:32.452994  4538 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14: Generated new TSK 0
I20260812 06:18:32.453187  4538 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:32.460932  4041 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:32.462627  4557 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:32.462728  4561 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:32.462733  4041 server_base.cc:1061] running on GCE node
W20260812 06:18:32.462901  4565 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:32.463125  4041 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:32.463167  4041 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:32.463187  4041 hybrid_clock.cc:648] HybridClock initialized: now 1786515512463187 us; error 0 us; skew 500 ppm
I20260812 06:18:32.463954  4041 webserver.cc:533] Webserver started at http://127.3.242.65:38305/ using document root <none> and password file <none>
I20260812 06:18:32.464107  4041 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:32.464157  4041 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:32.464232  4041 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:32.464560  4041 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/instance:
uuid: "6752f8d39f294e6aa2de92b677a917d0"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-266d"
I20260812 06:18:32.465945  4041 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:32.466755  4573 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.466962  4041 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:32.467027  4041 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root
uuid: "6752f8d39f294e6aa2de92b677a917d0"
format_stamp: "Formatted at 2026-08-12 06:18:32 on dist-test-slave-266d"
I20260812 06:18:32.467088  4041 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:32.476995  4041 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:32.477295  4041 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:32.477540  4041 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:32.477934  4041 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:32.477970  4041 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.478008  4041 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:32.478036  4041 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:32.481994  4041 rpc_server.cc:307] RPC server started. Bound to: 127.3.242.65:34641
I20260812 06:18:32.482779  4687 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.242.65:34641 every 8 connection(s)
I20260812 06:18:32.486642  4689 heartbeater.cc:344] Connected to a master server at 127.3.242.126:35843
I20260812 06:18:32.486722  4689 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:32.486922  4689 heartbeater.cc:507] Master 127.3.242.126:35843 requested a full tablet report, sending...
I20260812 06:18:32.487465  4451 ts_manager.cc:194] Registered new tserver with Master: 6752f8d39f294e6aa2de92b677a917d0 (127.3.242.65:34641)
I20260812 06:18:32.488097  4451 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42400
I20260812 06:18:32.488160  4041 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005550894s
I20260812 06:18:32.494230  4451 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42406:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:32.501873  4618 tablet_service.cc:1511] Processing CreateTablet for tablet e0335e3ef5fe443a8070fb95455ea65e (DEFAULT_TABLE table=heavy-update-compaction-test [id=834e2ac0c1414019bc5c05059872cd34]), partition=
I20260812 06:18:32.502089  4618 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e0335e3ef5fe443a8070fb95455ea65e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:32.503764  4712 tablet_bootstrap.cc:492] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Bootstrap starting.
I20260812 06:18:32.504596  4712 tablet_bootstrap.cc:654] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:32.505523  4712 tablet_bootstrap.cc:492] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: No bootstrap required, opened a new log
I20260812 06:18:32.505596  4712 ts_tablet_manager.cc:1403] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:32.505959  4712 raft_consensus.cc:359] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6752f8d39f294e6aa2de92b677a917d0" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 34641 } }
I20260812 06:18:32.506038  4712 raft_consensus.cc:385] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:32.506073  4712 raft_consensus.cc:740] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6752f8d39f294e6aa2de92b677a917d0, State: Initialized, Role: FOLLOWER
I20260812 06:18:32.506193  4712 consensus_queue.cc:260] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [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: "6752f8d39f294e6aa2de92b677a917d0" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 34641 } }
I20260812 06:18:32.506261  4712 raft_consensus.cc:399] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:32.506305  4712 raft_consensus.cc:493] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:32.506356  4712 raft_consensus.cc:3060] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:32.507025  4712 raft_consensus.cc:515] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6752f8d39f294e6aa2de92b677a917d0" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 34641 } }
I20260812 06:18:32.507156  4712 leader_election.cc:304] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [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: 6752f8d39f294e6aa2de92b677a917d0; no voters: 
I20260812 06:18:32.507344  4712 leader_election.cc:290] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:32.507439  4717 raft_consensus.cc:2804] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:32.507634  4712 ts_tablet_manager.cc:1434] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:32.507664  4717 raft_consensus.cc:697] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 1 LEADER]: Becoming Leader. State: Replica: 6752f8d39f294e6aa2de92b677a917d0, State: Running, Role: LEADER
I20260812 06:18:32.507819  4689 heartbeater.cc:499] Master 127.3.242.126:35843 was elected leader, sending a full tablet report...
I20260812 06:18:32.507822  4717 consensus_queue.cc:237] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [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: "6752f8d39f294e6aa2de92b677a917d0" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 34641 } }
I20260812 06:18:32.509127  4451 catalog_manager.cc:5719] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6752f8d39f294e6aa2de92b677a917d0 (127.3.242.65). New cstate: current_term: 1 leader_uuid: "6752f8d39f294e6aa2de92b677a917d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6752f8d39f294e6aa2de92b677a917d0" member_type: VOTER last_known_addr { host: "127.3.242.65" port: 34641 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:32.561303  4041 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.015s	sys 0.007s
I20260812 06:18:32.733312  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=23.023690
I20260812 06:18:32.894372  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.161s	user 0.131s	sys 0.028s Metrics: {"bytes_written":15999660,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":36,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":676,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44953,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"update_count":1950}
I20260812 06:18:32.894979  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling LogGCOp(e0335e3ef5fe443a8070fb95455ea65e): free 32761802 bytes of WAL
I20260812 06:18:32.895218  4582 log_reader.cc:385] T e0335e3ef5fe443a8070fb95455ea65e: removed 3 log segments from log reader
I20260812 06:18:32.895268  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000001 (ops 1-6)
I20260812 06:18:32.895305  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000002 (ops 7-11)
I20260812 06:18:32.895339  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000003 (ops 12-16)
I20260812 06:18:32.900741  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: LogGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:32.901212  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e): 20924070 bytes on disk
I20260812 06:18:32.901619  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.902051  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:32.914763  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.915165  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:33.078486  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.163s	user 0.103s	sys 0.060s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24446412,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":12291,"lbm_reads_lt_1ms":554,"lbm_write_time_us":28035,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":318,"threads_started":5,"update_count":2450}
I20260812 06:18:33.079041  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:33.123225  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.044s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.123773  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:33.269338  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.145s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754122,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":805,"lbm_read_time_us":10854,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20310,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":52864,"update_count":2000}
I20260812 06:18:33.269930  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:33.319629  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.049s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16409913,"delete_count":0,"lbm_write_time_us":18859,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.320186  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:33.329959  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.330451  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:33.527288  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.197s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856665,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":12128,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30539,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:33.527863  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:33.579504  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23176,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.580036  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:33.592082  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.592742  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:33.749157  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.156s	user 0.128s	sys 0.015s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1892,"lbm_read_time_us":9561,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32255,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":769,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:33.750092  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=10.126437
I20260812 06:18:33.800957  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.051s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20624,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.801558  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:33.816635  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.817188  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:33.959018  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.142s	user 0.114s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20754242,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":10373,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26699,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:33.959596  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=10.126437
I20260812 06:18:34.009533  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.050s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16544,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.010078  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:34.024875  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.025415  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:34.144949  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.119s	user 0.087s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20754242,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":9944,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20075,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:18:34.145483  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=10.126437
I20260812 06:18:34.193531  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13526,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.194038  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:34.204206  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.204602  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:34.234607  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.030s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1337,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1319,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:34.235216  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e): 472 bytes on disk
I20260812 06:18:34.235615  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e) 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:34.236109  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:34.400828  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.165s	user 0.122s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20754241,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1240,"lbm_read_time_us":10148,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24755,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:34.401382  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling LogGCOp(e0335e3ef5fe443a8070fb95455ea65e): free 121006376 bytes of WAL
I20260812 06:18:34.401588  4582 log_reader.cc:385] T e0335e3ef5fe443a8070fb95455ea65e: removed 12 log segments from log reader
I20260812 06:18:34.401634  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000004 (ops 17-21)
I20260812 06:18:34.401674  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000005 (ops 22-26)
I20260812 06:18:34.401708  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000006 (ops 27-31)
I20260812 06:18:34.401770  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000007 (ops 32-36)
I20260812 06:18:34.401810  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000008 (ops 37-41)
I20260812 06:18:34.401872  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000009 (ops 42-46)
I20260812 06:18:34.401907  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000010 (ops 47-51)
I20260812 06:18:34.401961  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000011 (ops 52-56)
I20260812 06:18:34.401996  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000012 (ops 57-61)
I20260812 06:18:34.402040  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000013 (ops 62-66)
I20260812 06:18:34.402073  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000014 (ops 67-70)
I20260812 06:18:34.402127  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000015 (ops 71-75)
I20260812 06:18:34.423660  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: LogGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.022s	user 0.001s	sys 0.018s Metrics: {}
I20260812 06:18:34.424144  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:34.469647  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.045s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.470080  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=3.181125
I20260812 06:18:34.497269  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.027s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6262,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:34.497709  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:34.506736  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3439,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.507097  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:34.703315  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.196s	user 0.131s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959176,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":194,"lbm_read_time_us":14124,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32887,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":3000}
I20260812 06:18:34.703876  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:34.752386  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.048s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17036,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.752912  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:34.763239  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.763638  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:34.935662  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.172s	user 0.107s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856656,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":497,"lbm_read_time_us":12560,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26317,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2500}
I20260812 06:18:34.936115  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:34.986923  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.051s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.987465  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.006879  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.019s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.007496  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:35.189360  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.182s	user 0.105s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":793,"lbm_read_time_us":13987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27077,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2500}
I20260812 06:18:35.189805  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:35.235548  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19538,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.236099  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.251339  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5856,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.251907  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:35.423930  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.172s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856656,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":969,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26595,"lbm_writes_lt_1ms":543,"mutex_wait_us":390,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:35.424400  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:35.473184  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21079,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.473685  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.483091  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.483644  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:35.620621  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.137s	user 0.118s	sys 0.017s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856649,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":8591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27516,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":58624,"update_count":2500}
I20260812 06:18:35.621166  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=11.118625
I20260812 06:18:35.667035  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.046s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19743,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:35.667490  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.678686  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.679119  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.691354  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.691741  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:35.722548  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":1211,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1556,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:35.723191  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling LogGCOp(e0335e3ef5fe443a8070fb95455ea65e): free 124257323 bytes of WAL
I20260812 06:18:35.723409  4582 log_reader.cc:385] T e0335e3ef5fe443a8070fb95455ea65e: removed 12 log segments from log reader
I20260812 06:18:35.723459  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000016 (ops 76-80)
I20260812 06:18:35.723486  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000017 (ops 81-85)
I20260812 06:18:35.723519  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000018 (ops 86-90)
I20260812 06:18:35.723551  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000019 (ops 91-95)
I20260812 06:18:35.723583  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000020 (ops 96-100)
I20260812 06:18:35.723614  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000021 (ops 101-105)
I20260812 06:18:35.723645  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000022 (ops 106-110)
I20260812 06:18:35.723677  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000023 (ops 111-115)
I20260812 06:18:35.723708  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000024 (ops 116-120)
I20260812 06:18:35.723738  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000025 (ops 121-125)
I20260812 06:18:35.723770  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000026 (ops 126-130)
I20260812 06:18:35.723801  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000027 (ops 131-134)
I20260812 06:18:35.746014  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: LogGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:35.746459  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e): 483 bytes on disk
I20260812 06:18:35.746896  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:35.747452  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=3.181125
I20260812 06:18:35.758272  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:35.758648  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:35.775349  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.017s	user 0.004s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3362,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:35.775800  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:35.993444  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.217s	user 0.128s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33061817,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":867,"lbm_read_time_us":14200,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38785,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":70,"threads_started":1,"update_count":3500}
I20260812 06:18:35.994040  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:36.050554  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.056s	user 0.015s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15983,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.051102  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:36.065982  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.066505  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:36.250291  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.184s	user 0.139s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":792,"lbm_read_time_us":12412,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33180,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":53888,"update_count":2500}
I20260812 06:18:36.250880  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:36.310667  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.060s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19337,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.311194  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:36.321798  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.322191  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:36.499980  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.178s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":11369,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26913,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.500821  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:36.545620  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.045s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":16534,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.546211  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:36.555786  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.556268  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:36.741322  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.185s	user 0.113s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856650,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"lbm_read_time_us":10532,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28791,"lbm_writes_lt_1ms":543,"mutex_wait_us":492,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:36.741837  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=14.095187
I20260812 06:18:36.786665  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.045s	user 0.023s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":15716,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.787212  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:36.801879  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.802292  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:36.946854  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.144s	user 0.122s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856657,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":739,"lbm_read_time_us":8817,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27121,"lbm_writes_lt_1ms":543,"mutex_wait_us":231,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:36.947628  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=11.118625
I20260812 06:18:36.987833  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16757,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.988324  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:37.005316  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.017s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3721,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.005828  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:37.020134  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.020648  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:37.159165  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.138s	user 0.098s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856764,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":460,"lbm_read_time_us":9428,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27686,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:37.159982  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=11.118625
I20260812 06:18:37.202035  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.042s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16089,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:37.202509  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:37.213380  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.213851  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:37.226454  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.226831  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:37.256963  4041 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.696s	user 1.714s	sys 0.152s
I20260812 06:18:37.258888  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushMRSOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.032s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1136,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1427,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:37.259486  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling LogGCOp(e0335e3ef5fe443a8070fb95455ea65e): free 133024646 bytes of WAL
I20260812 06:18:37.259685  4582 log_reader.cc:385] T e0335e3ef5fe443a8070fb95455ea65e: removed 13 log segments from log reader
I20260812 06:18:37.259729  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000028 (ops 135-139)
I20260812 06:18:37.259758  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000029 (ops 140-145)
I20260812 06:18:37.259800  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000030 (ops 146-150)
I20260812 06:18:37.259836  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000031 (ops 151-155)
I20260812 06:18:37.259869  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000032 (ops 156-160)
I20260812 06:18:37.259902  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000033 (ops 161-165)
I20260812 06:18:37.259933  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000034 (ops 166-170)
I20260812 06:18:37.259968  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000035 (ops 171-174)
I20260812 06:18:37.259992  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000036 (ops 175-179)
I20260812 06:18:37.260015  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000037 (ops 180-184)
I20260812 06:18:37.260036  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000038 (ops 185-188)
I20260812 06:18:37.260059  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000039 (ops 189-193)
I20260812 06:18:37.260082  4582 log.cc:1079] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: Deleting log segment in path: /tmp/dist-test-taskC6RtjG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507343311-4041-0/minicluster-data/ts-0-root/wals/e0335e3ef5fe443a8070fb95455ea65e/wal-000000040 (ops 194-198)
I20260812 06:18:37.280369  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: LogGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.021s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:18:37.280849  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=2.188937
I20260812 06:18:37.297631  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: FlushDeltaMemStoresOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":500}
I20260812 06:18:37.298087  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e): 492 bytes on disk
I20260812 06:18:37.298465  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: UndoDeltaBlockGCOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.298960  4692 maintenance_manager.cc:419] P 6752f8d39f294e6aa2de92b677a917d0: Scheduling MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e): perf score=1.000000
I20260812 06:18:37.311196  4041 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.001s	sys 0.000s
I20260812 06:18:37.311636  4041 tablet_server.cc:179] TabletServer@127.3.242.65:0 shutting down...
I20260812 06:18:37.417168  4582 maintenance_manager.cc:643] P 6752f8d39f294e6aa2de92b677a917d0: MajorDeltaCompactionOp(e0335e3ef5fe443a8070fb95455ea65e) complete. Timing: real 0.118s	user 0.105s	sys 0.012s Metrics: {"cfile_cache_hit":533,"cfile_cache_hit_bytes":24856764,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2632,"lbm_read_time_us":2032,"lbm_reads_lt_1ms":113,"lbm_write_time_us":25613,"lbm_writes_lt_1ms":643,"mutex_wait_us":974,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19584,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:37.417742  4041 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:37.418059  4041 tablet_replica.cc:333] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0: stopping tablet replica
I20260812 06:18:37.418188  4041 raft_consensus.cc:2243] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.418350  4041 raft_consensus.cc:2272] T e0335e3ef5fe443a8070fb95455ea65e P 6752f8d39f294e6aa2de92b677a917d0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.432647  4041 tablet_server.cc:196] TabletServer@127.3.242.65:0 shutdown complete.
I20260812 06:18:37.467280  4041 master.cc:562] Master@127.3.242.126:35843 shutting down...
I20260812 06:18:37.470374  4041 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:37.470527  4041 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:37.470577  4041 tablet_replica.cc:333] T 00000000000000000000000000000000 P a457b5ff3435418ca3a3a5b2e0e20c14: stopping tablet replica
I20260812 06:18:37.483517  4041 master.cc:584] Master@127.3.242.126:35843 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5166 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10198 ms total)

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