/build/source/nativelink-scheduler/src/simple_scheduler.rs
Line | Count | Source |
1 | | // Copyright 2024 The NativeLink Authors. All rights reserved. |
2 | | // |
3 | | // Licensed under the Functional Source License, Version 1.1, Apache 2.0 Future License (the "License"); |
4 | | // you may not use this file except in compliance with the License. |
5 | | // You may obtain a copy of the License at |
6 | | // |
7 | | // See LICENSE file for details |
8 | | // |
9 | | // Unless required by applicable law or agreed to in writing, software |
10 | | // distributed under the License is distributed on an "AS IS" BASIS, |
11 | | // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
12 | | // See the License for the specific language governing permissions and |
13 | | // limitations under the License. |
14 | | |
15 | | use core::sync::atomic::{AtomicUsize, Ordering}; |
16 | | use std::collections::{HashMap, HashSet, VecDeque}; |
17 | | use std::sync::Arc; |
18 | | use std::time::{Instant, SystemTime, UNIX_EPOCH}; |
19 | | |
20 | | use async_trait::async_trait; |
21 | | use futures::{Future, FutureExt, StreamExt, future}; |
22 | | use nativelink_config::schedulers::SimpleSpec; |
23 | | use nativelink_error::{Code, Error, ResultExt, make_err}; |
24 | | use nativelink_metric::{MetricsComponent, RootMetricsComponent}; |
25 | | use nativelink_proto::com::github::trace_machina::nativelink::events::{ |
26 | | Event, OriginEvent, RequestEvent, event, request_event, |
27 | | }; |
28 | | use nativelink_proto::com::github::trace_machina::nativelink::remote_execution::{ |
29 | | StartExecute, WorkerLoad, |
30 | | }; |
31 | | use nativelink_util::action_messages::{ActionInfo, ActionState, OperationId, WorkerId}; |
32 | | use nativelink_util::instant_wrapper::InstantWrapper; |
33 | | use nativelink_util::metrics::{ |
34 | | AgeBuckets, record_awaited_action_orphan, record_executing_ages, record_matching_pass, |
35 | | record_parked_dispatched, record_queue_ages, record_queue_depth, record_sweep_failure, |
36 | | record_unsatisfiable_failed, record_unsatisfiable_queued, |
37 | | }; |
38 | | use nativelink_util::operation_state_manager::{ |
39 | | ActionStateResult, ActionStateResultStream, ClientStateManager, MatchingEngineStateManager, |
40 | | OperationFilter, OperationStageFlags, OrderDirection, UpdateOperationType, |
41 | | }; |
42 | | use nativelink_util::origin_event::{OriginMetadata, get_node_id}; |
43 | | use nativelink_util::platform_properties::PlatformProperties; |
44 | | use nativelink_util::shutdown_guard::ShutdownGuard; |
45 | | use nativelink_util::spawn; |
46 | | use nativelink_util::task::JoinHandleDropGuard; |
47 | | use opentelemetry::KeyValue; |
48 | | use opentelemetry::baggage::BaggageExt; |
49 | | use opentelemetry::context::{Context, FutureExt as OtelFutureExt}; |
50 | | use opentelemetry_semantic_conventions::attribute::ENDUSER_ID; |
51 | | use parking_lot::Mutex; |
52 | | use tokio::sync::{Notify, mpsc}; |
53 | | use tokio::time::Duration; |
54 | | use tracing::{debug, error, info, info_span, warn}; |
55 | | use uuid::Uuid; |
56 | | |
57 | | use crate::api_worker_scheduler::{ApiWorkerScheduler, QueuedAction}; |
58 | | use crate::awaited_action_db::{AwaitedActionDb, CLIENT_KEEPALIVE_DURATION, PeerScheduler}; |
59 | | use crate::known_platform_property_provider::KnownPlatformPropertyProvider; |
60 | | use crate::match_outcome::{MatchOutcome, PropertyShape, UnsatisfiableReason}; |
61 | | use crate::platform_property_manager::PlatformPropertyManager; |
62 | | use crate::simple_scheduler_state_manager::{ |
63 | | RetryLimits, SimpleSchedulerStateManager, is_lost_record, |
64 | | }; |
65 | | use crate::unsatisfiable_tracker::UnsatisfiableTracker; |
66 | | use crate::worker::{ActionInfoWithProps, Worker, WorkerTimestamp}; |
67 | | use crate::worker_registry::WorkerRegistry; |
68 | | use crate::worker_scheduler::{WorkerScheduler, WorkerSummary}; |
69 | | |
70 | | /// Default timeout for workers in seconds: four default keepalive intervals |
71 | | /// (2.5s each). The old value of two meant one late keepalive under load |
72 | | /// evicted the worker and requeued everything it held. |
73 | | /// If this changes, remember to change the documentation in the config. |
74 | | const DEFAULT_WORKER_TIMEOUT_S: u64 = 10; |
75 | | |
76 | | /// How often this scheduler tells its peers what its workers can run and |
77 | | /// reads what theirs can. |
78 | | const FLEET_EXCHANGE_INTERVAL: Duration = Duration::from_secs(5); |
79 | | |
80 | | /// How many exchange intervals a published fleet record outlives its last |
81 | | /// refresh, so one missed refresh does not make a peer's workers vanish. |
82 | | const FLEET_RECORD_TTL_INTERVALS: u32 = 3; |
83 | | |
84 | | /// Floor on how many queued actions one matching pass fails as unsatisfiable. |
85 | | /// The cap bleeds a large burst over several (back-to-back) passes instead of |
86 | | /// failing a whole shape-class at once, and bounds the cumulative |
87 | | /// version-conflict backoff sleeps a single pass can incur. |
88 | | const MAX_UNSATISFIABLE_FAILS_PER_PASS: usize = 16; |
89 | | |
90 | | /// A backlog larger than `floor * DIVISOR` raises the cap to `backlog / |
91 | | /// DIVISOR`, so a large single-shape burst drains in ~DIVISOR back-to-back |
92 | | /// passes rather than `backlog / floor` of them (whose tail could outlast a |
93 | | /// client's own timeout). |
94 | | const UNSATISFIABLE_FAIL_BACKLOG_DIVISOR: usize = 4; |
95 | | |
96 | | /// The per-pass unsatisfiable-fail cap for a pass, given the previous pass's |
97 | | /// unsatisfiable backlog: the floor, or a fraction of the backlog if larger. |
98 | 869 | const fn unsatisfiable_fail_cap(last_backlog: usize) -> usize { |
99 | 869 | let scaled = last_backlog / UNSATISFIABLE_FAIL_BACKLOG_DIVISOR; |
100 | 869 | if scaled > MAX_UNSATISFIABLE_FAILS_PER_PASS { |
101 | 2 | scaled |
102 | | } else { |
103 | 867 | MAX_UNSATISFIABLE_FAILS_PER_PASS |
104 | | } |
105 | 869 | } |
106 | | |
107 | | /// Default timeout for a sent kill to be acknowledged in seconds. |
108 | | /// If this changes, remember to change the documentation in the config. |
109 | | const DEFAULT_UNACKNOWLEDGED_KILL_TIMEOUT_S: u64 = 60; |
110 | | |
111 | | /// Mark operations as completed with error if no client has updated them |
112 | | /// within this duration. |
113 | | /// If this changes, remember to change the documentation in the config. |
114 | | pub(crate) const DEFAULT_CLIENT_ACTION_TIMEOUT_S: u64 = 60; |
115 | | |
116 | | /// Default times a job can retry before failing. |
117 | | /// If this changes, remember to change the documentation in the config. |
118 | | const DEFAULT_MAX_JOB_RETRIES: usize = 3; |
119 | | |
120 | | struct SimpleSchedulerActionStateResult { |
121 | | client_operation_id: OperationId, |
122 | | action_state_result: Box<dyn ActionStateResult>, |
123 | | } |
124 | | |
125 | | impl SimpleSchedulerActionStateResult { |
126 | 255 | fn new( |
127 | 255 | client_operation_id: OperationId, |
128 | 255 | action_state_result: Box<dyn ActionStateResult>, |
129 | 255 | ) -> Self { |
130 | 255 | Self { |
131 | 255 | client_operation_id, |
132 | 255 | action_state_result, |
133 | 255 | } |
134 | 255 | } |
135 | | } |
136 | | |
137 | | #[async_trait] |
138 | | impl ActionStateResult for SimpleSchedulerActionStateResult { |
139 | 105 | async fn as_state(&self) -> Result<(Arc<ActionState>, Option<OriginMetadata>), Error> { |
140 | | let (mut action_state, origin_metadata) = self |
141 | | .action_state_result |
142 | | .as_state() |
143 | | .await |
144 | | .err_tip(|| "In SimpleSchedulerActionStateResult")?; |
145 | | // We need to ensure the client is not aware of the downstream |
146 | | // operation id, so override it before it goes out. |
147 | | Arc::make_mut(&mut action_state).client_operation_id = self.client_operation_id.clone(); |
148 | | Ok((action_state, origin_metadata)) |
149 | 105 | } |
150 | | |
151 | 67 | async fn changed(&mut self) -> Result<(Arc<ActionState>, Option<OriginMetadata>), Error> { |
152 | | let (mut action_state, origin_metadata) = self |
153 | | .action_state_result |
154 | | .changed() |
155 | | .await |
156 | | .err_tip(|| "In SimpleSchedulerActionStateResult")?; |
157 | | // We need to ensure the client is not aware of the downstream |
158 | | // operation id, so override it before it goes out. |
159 | | Arc::make_mut(&mut action_state).client_operation_id = self.client_operation_id.clone(); |
160 | | Ok((action_state, origin_metadata)) |
161 | 67 | } |
162 | | |
163 | 0 | async fn as_action_info(&self) -> Result<(Arc<ActionInfo>, Option<OriginMetadata>), Error> { |
164 | | self.action_state_result |
165 | | .as_action_info() |
166 | | .await |
167 | | .err_tip(|| "In SimpleSchedulerActionStateResult") |
168 | 0 | } |
169 | | } |
170 | | |
171 | | /// Engine used to manage the queued/running tasks and relationship with |
172 | | /// the worker nodes. All state on how the workers and actions are interacting |
173 | | /// should be held in this struct. |
174 | | #[derive(MetricsComponent)] |
175 | | pub struct SimpleScheduler { |
176 | | /// Manager for matching engine side of the state manager. |
177 | | #[metric(group = "matching_engine_state_manager")] |
178 | | matching_engine_state_manager: Arc<dyn MatchingEngineStateManager>, |
179 | | |
180 | | /// Manager for client state of this scheduler. |
181 | | #[metric(group = "client_state_manager")] |
182 | | client_state_manager: Arc<dyn ClientStateManager>, |
183 | | |
184 | | /// Manager for platform of this scheduler. |
185 | | #[metric(group = "platform_properties")] |
186 | | platform_property_manager: Arc<PlatformPropertyManager>, |
187 | | |
188 | | /// A `Workers` pool that contains all workers that are available to execute actions in a priority |
189 | | /// order based on the allocation strategy. |
190 | | #[metric(group = "worker_scheduler")] |
191 | | worker_scheduler: Arc<ApiWorkerScheduler>, |
192 | | |
193 | | /// The sender to send origin events to the origin events. |
194 | | maybe_origin_event_tx: Option<mpsc::Sender<OriginEvent>>, |
195 | | |
196 | | /// Background task that tries to match actions to workers. If this struct |
197 | | /// is dropped the spawn will be cancelled as well. |
198 | | task_worker_matching_spawn: JoinHandleDropGuard<()>, |
199 | | |
200 | | /// Background task that retires queued actions nobody is waiting on. |
201 | | /// Dropped with the struct, like the matching task. |
202 | | task_abandoned_sweep_spawn: JoinHandleDropGuard<()>, |
203 | | |
204 | | /// Background task that retires executing actions whose worker has gone |
205 | | /// quiet or no longer runs them. Dropped with the struct; `None` when |
206 | | /// `executing_sweep_interval_s` disables it. |
207 | | task_executing_sweep_spawn: Option<JoinHandleDropGuard<()>>, |
208 | | |
209 | | /// Background task that swaps worker capabilities with peer schedulers |
210 | | /// on the same state. Dropped with the struct, like the matching task. |
211 | | task_fleet_exchange_spawn: JoinHandleDropGuard<()>, |
212 | | |
213 | | /// Every duration, do logging of worker matching |
214 | | /// e.g. "worker busy", "can't find any worker" |
215 | | /// Set to None to disable. This is quite noisy, so we limit it |
216 | | worker_match_logging_interval: Option<Duration>, |
217 | | |
218 | | /// How long each action property shape has gone without any worker able |
219 | | /// to run it. |
220 | | unsatisfiable_tracker: Mutex<UnsatisfiableTracker>, |
221 | | /// The clock for actions queued while no worker is connected anywhere |
222 | | /// (`no_worker_action_timeout_s`); `None` when that timeout is off. |
223 | | no_worker_tracker: Option<Mutex<UnsatisfiableTracker>>, |
224 | | |
225 | | /// Typed platform properties by the hash of the raw ones. Typing is a |
226 | | /// lookup and a parse per property per queued action per pass, and the |
227 | | /// raw properties of a queued action rarely change (an escalation is |
228 | | /// the exception, and it changes the hash), so the pass reuses the |
229 | | /// typed set. Cleared when full rather than evicted, like |
230 | | /// `static_verdicts`. |
231 | | typed_properties: Mutex<HashMap<u64, PlatformProperties>>, |
232 | | |
233 | | /// The number of unsatisfiable actions still queued at the end of the last |
234 | | /// matching pass, used to size the next pass's per-pass fail cap so a large |
235 | | /// burst drains in a few passes. See `unsatisfiable_fail_cap`. |
236 | | last_unsatisfiable_backlog: AtomicUsize, |
237 | | |
238 | | /// The clock the state manager uses. |
239 | | now_fn: Box<dyn Fn() -> SystemTime + Send + Sync>, |
240 | | } |
241 | | |
242 | | impl core::fmt::Debug for SimpleScheduler { |
243 | 0 | fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { |
244 | 0 | f.debug_struct("SimpleScheduler") |
245 | 0 | .field("platform_property_manager", &self.platform_property_manager) |
246 | 0 | .field("worker_scheduler", &self.worker_scheduler) |
247 | 0 | .field("maybe_origin_event_tx", &self.maybe_origin_event_tx) |
248 | 0 | .field( |
249 | 0 | "task_worker_matching_spawn", |
250 | 0 | &self.task_worker_matching_spawn, |
251 | 0 | ) |
252 | 0 | .field( |
253 | 0 | "task_abandoned_sweep_spawn", |
254 | 0 | &self.task_abandoned_sweep_spawn, |
255 | 0 | ) |
256 | 0 | .field( |
257 | 0 | "task_executing_sweep_spawn", |
258 | 0 | &self.task_executing_sweep_spawn, |
259 | 0 | ) |
260 | 0 | .field("task_fleet_exchange_spawn", &self.task_fleet_exchange_spawn) |
261 | 0 | .finish_non_exhaustive() |
262 | 0 | } |
263 | | } |
264 | | |
265 | | /// How many typed property sets the pass keeps before starting over. |
266 | | const MAX_TYPED_PROPERTIES: usize = 10_000; |
267 | | |
268 | | /// The typed form of an action's raw properties, from the cache when the |
269 | | /// same raw set was typed before. |
270 | 588 | fn typed_properties_for( |
271 | 588 | cache: &Mutex<HashMap<u64, PlatformProperties>>, |
272 | 588 | manager: &PlatformPropertyManager, |
273 | 588 | raw: &HashMap<String, String>, |
274 | 588 | ) -> Result<PlatformProperties, Error> { |
275 | | use core::hash::{Hash, Hasher}; |
276 | 588 | let mut pairs: Vec<(&String, &String)> = raw.iter().collect(); |
277 | 588 | pairs.sort(); |
278 | 588 | let mut hasher = std::collections::hash_map::DefaultHasher::new(); |
279 | 1.04k | for (name, value) in &pairs588 { |
280 | 1.04k | name.hash(&mut hasher); |
281 | 1.04k | value.hash(&mut hasher); |
282 | 1.04k | } |
283 | 588 | let key = hasher.finish(); |
284 | 588 | if let Some(typed443 ) = cache.lock().get(&key) { |
285 | 443 | return Ok(typed.clone()); |
286 | 145 | } |
287 | 145 | let typed = manager.make_platform_properties(raw.clone())?0 ; |
288 | 145 | let mut cache = cache.lock(); |
289 | 145 | if cache.len() >= MAX_TYPED_PROPERTIES { |
290 | 0 | cache.clear(); |
291 | 145 | } |
292 | 145 | cache.insert(key, typed.clone()); |
293 | 145 | Ok(typed) |
294 | 588 | } |
295 | | |
296 | | impl SimpleScheduler { |
297 | 1 | fn origin_event_id(event: &Event) -> String { |
298 | 1 | Uuid::now_v6(&get_node_id(Some(event))) |
299 | 1 | .hyphenated() |
300 | 1 | .to_string() |
301 | 1 | } |
302 | | |
303 | 1 | fn scheduler_start_execute_event( |
304 | 1 | worker_id: &WorkerId, |
305 | 1 | operation_id: &OperationId, |
306 | 1 | action_info: &ActionInfoWithProps, |
307 | 1 | ) -> Event { |
308 | 1 | let start_execute = StartExecute { |
309 | 1 | execute_request: Some(action_info.inner.as_ref().into()), |
310 | 1 | operation_id: operation_id.to_string(), |
311 | 1 | queued_timestamp: Some(action_info.inner.insert_timestamp.into()), |
312 | 1 | platform: Some((&action_info.platform_properties).into()), |
313 | 1 | worker_id: worker_id.to_string(), |
314 | 1 | request_metadata: action_info.origin_metadata.bazel_metadata.clone(), |
315 | 1 | }; |
316 | 1 | Event { |
317 | 1 | event: Some(event::Event::Request(RequestEvent { |
318 | 1 | event: Some(request_event::Event::SchedulerStartExecute(start_execute)), |
319 | 1 | })), |
320 | 1 | } |
321 | 1 | } |
322 | | |
323 | 1 | async fn publish_scheduler_start_execute( |
324 | 1 | maybe_origin_event_tx: Option<&mpsc::Sender<OriginEvent>>, |
325 | 1 | origin_metadata: &OriginMetadata, |
326 | 1 | event_id: String, |
327 | 1 | event: Event, |
328 | 1 | ) { |
329 | 1 | let Some(origin_event_tx) = maybe_origin_event_tx else { |
330 | 0 | return; |
331 | | }; |
332 | | |
333 | 1 | let origin_event = OriginEvent { |
334 | 1 | version: 0, |
335 | 1 | event_id, |
336 | 1 | parent_event_id: String::new(), |
337 | 1 | bazel_request_metadata: origin_metadata.bazel_metadata.clone(), |
338 | 1 | identity: origin_metadata.identity.clone(), |
339 | 1 | event: Some(event), |
340 | 1 | }; |
341 | | |
342 | | // Awaited send (not try_send): backpressure rather than drop, so the |
343 | | // start-execute event that later resource-usage events reference as |
344 | | // their parent isn't silently lost when the queue is full. |
345 | 1 | if let Err(err0 ) = origin_event_tx.send(origin_event).await { |
346 | 0 | warn!( |
347 | | ?err, |
348 | | "Failed to publish scheduler start execute origin event" |
349 | | ); |
350 | 1 | } |
351 | 1 | } |
352 | | |
353 | | /// Attempts to find a worker to execute an action and begins executing it. |
354 | | /// If an action is already running that is cacheable it may merge this |
355 | | /// action with the results and state changes of the already running |
356 | | /// action. If the task cannot be executed immediately it will be queued |
357 | | /// for execution based on priority and other metrics. |
358 | | /// All further updates to the action will be provided through the returned |
359 | | /// value. |
360 | 255 | async fn inner_add_action( |
361 | 255 | &self, |
362 | 255 | client_operation_id: OperationId, |
363 | 255 | action_info: Arc<ActionInfo>, |
364 | 255 | ) -> Result<Box<dyn ActionStateResult>, Error> { |
365 | 255 | let action_state_result = self |
366 | 255 | .client_state_manager |
367 | 255 | .add_action(client_operation_id.clone(), action_info) |
368 | 255 | .await |
369 | 255 | .err_tip(|| "In SimpleScheduler::add_action")?0 ; |
370 | 255 | Ok(Box::new(SimpleSchedulerActionStateResult::new( |
371 | 255 | client_operation_id.clone(), |
372 | 255 | action_state_result, |
373 | 255 | ))) |
374 | 255 | } |
375 | | |
376 | 512 | async fn inner_filter_operations( |
377 | 512 | &self, |
378 | 512 | filter: OperationFilter, |
379 | 512 | ) -> Result<ActionStateResultStream<'_>, Error> { |
380 | 512 | self.client_state_manager |
381 | 512 | .filter_operations(filter) |
382 | 512 | .await |
383 | 512 | .err_tip(|| "In SimpleScheduler::find_by_client_operation_id getting filter result") |
384 | 512 | } |
385 | | |
386 | 864 | async fn get_queued_operations(&self) -> Result<ActionStateResultStream<'_>, Error> { |
387 | 864 | let filter = OperationFilter { |
388 | 864 | stages: OperationStageFlags::Queued, |
389 | 864 | order_by_priority_direction: Some(OrderDirection::Desc), |
390 | 864 | ..Default::default() |
391 | 864 | }; |
392 | 864 | self.matching_engine_state_manager |
393 | 864 | .filter_operations(filter) |
394 | 864 | .await |
395 | 861 | .err_tip(|| "In SimpleScheduler::get_queued_operations getting filter result") |
396 | 861 | } |
397 | | |
398 | 137 | pub async fn do_try_match_for_test(&self) -> Result<(), Error> { |
399 | 137 | self.do_try_match(true).await |
400 | 137 | } |
401 | | |
402 | | /// A pass as production runs it between logging intervals: cached |
403 | | /// verdicts are used rather than recomputed. |
404 | 7 | pub async fn do_try_match_quietly_for_test(&self) -> Result<(), Error> { |
405 | 7 | self.do_try_match(false).await |
406 | 7 | } |
407 | | |
408 | | /// Stands in for the fleet exchange with peer schedulers: one peer with |
409 | | /// these workers. |
410 | 7 | pub async fn set_peer_fleet_for_test(&self, peer_fleet: Vec<PlatformProperties>)0 { |
411 | 7 | self.set_peer_schedulers_for_test(vec![PeerScheduler { |
412 | 7 | scheduler_id: "peer".to_string(), |
413 | 7 | workers: peer_fleet, |
414 | 7 | }]) |
415 | 7 | .await; |
416 | 7 | } |
417 | | |
418 | | /// Stands in for the fleet exchange with peer schedulers. |
419 | 9 | pub async fn set_peer_schedulers_for_test(&self, peers: Vec<PeerScheduler>) { |
420 | 9 | self.worker_scheduler |
421 | 9 | .set_peer_fleet(Some(peers), (self.now_fn)()) |
422 | 9 | .await; |
423 | 9 | } |
424 | | |
425 | | /// The id this scheduler publishes to its peers under. |
426 | 0 | pub fn scheduler_id_for_test(&self) -> &str { |
427 | 0 | self.worker_scheduler.scheduler_id() |
428 | 0 | } |
429 | | |
430 | | /// The workers held for a queued action right now. |
431 | 38 | pub async fn held_workers_for_test(&self) -> Vec<WorkerId>0 { |
432 | 38 | self.worker_scheduler.held_workers_for_test().await |
433 | 38 | } |
434 | | |
435 | | /// Stands in for a failed fleet exchange with peer schedulers. |
436 | 2 | pub async fn set_peers_unknown_for_test(&self)0 { |
437 | 2 | self.worker_scheduler |
438 | 2 | .set_peer_fleet(None, (self.now_fn)()) |
439 | 2 | .await; |
440 | 2 | } |
441 | | |
442 | | /// A counter that changes every time the fleet does. |
443 | 3 | pub async fn fleet_generation_for_test(&self) -> u640 { |
444 | 3 | self.worker_scheduler.fleet_generation().await |
445 | 3 | } |
446 | | |
447 | | /// What this scheduler would publish to peer schedulers. |
448 | 1 | pub async fn fleet_shapes_for_test(&self) -> Vec<PlatformProperties>0 { |
449 | 1 | self.worker_scheduler.fleet_shapes().await |
450 | 1 | } |
451 | | |
452 | | /// How long until the matching loop would next wake on behalf of an |
453 | | /// unsatisfiable shape, if at all. |
454 | 1 | pub fn unsatisfiable_deadline_for_test(&self) -> Option<Duration> { |
455 | 1 | self.unsatisfiable_deadline((self.now_fn)()) |
456 | 1 | } |
457 | | |
458 | | /// How long until a pass should run for an unsatisfiable or a no-worker |
459 | | /// shape, whichever comes first. |
460 | 824 | fn unsatisfiable_deadline(&self, now: SystemTime) -> Option<Duration> { |
461 | 824 | let unsatisfiable = self.unsatisfiable_tracker.lock().next_deadline(now); |
462 | 824 | let no_worker = self |
463 | 824 | .no_worker_tracker |
464 | 824 | .as_ref() |
465 | 824 | .and_then(|tracker| tracker.lock()6 .next_deadline6 (now6 )); |
466 | 824 | match (unsatisfiable, no_worker) { |
467 | 0 | (Some(a), Some(b)) => Some(a.min(b)), |
468 | 824 | (a, b) => a.or(b), |
469 | | } |
470 | 824 | } |
471 | | |
472 | | // TODO(palfrey) This is an O(n*m) (aka n^2) algorithm. In theory we |
473 | | // can create a map of capabilities of each worker and then try and match |
474 | | // the actions to the worker using the map lookup (ie. map reduce). |
475 | 864 | async fn do_try_match(&self, full_worker_logging: bool) -> Result<(), Error> { |
476 | 864 | let match_started = Instant::now(); |
477 | 864 | let result859 = self.do_try_match_inner(full_worker_logging).await; |
478 | 859 | record_matching_pass(match_started.elapsed().as_secs_f64(), result.is_ok()); |
479 | 859 | result |
480 | 859 | } |
481 | | |
482 | 864 | async fn do_try_match_inner(&self, full_worker_logging: bool) -> Result<(), Error> { |
483 | | struct UnsatisfiablePass<'a> { |
484 | | tracker: &'a Mutex<UnsatisfiableTracker>, |
485 | | now: SystemTime, |
486 | | fleet_generation: u64, |
487 | | /// Most actions this pass may fail as unsatisfiable (blast-radius |
488 | | /// cap, sized from the last pass's backlog by `unsatisfiable_fail_cap`). |
489 | | cap: usize, |
490 | | /// How many it has failed so far this pass. |
491 | | fails_this_pass: AtomicUsize, |
492 | | } |
493 | | |
494 | | /// Logs an action no worker can run and, once its property shape has |
495 | | /// been unsatisfiable for the configured timeout and the action has |
496 | | /// itself been queued that long, fails it. |
497 | 122 | async fn handle_unsatisfiable( |
498 | 122 | action_state_result: &dyn ActionStateResult, |
499 | 122 | matching_engine_state_manager: &dyn MatchingEngineStateManager, |
500 | 122 | workers: &ApiWorkerScheduler, |
501 | 122 | platform_properties: &PlatformProperties, |
502 | 122 | insert_timestamp: SystemTime, |
503 | 122 | reason: &UnsatisfiableReason, |
504 | 122 | pass: &UnsatisfiablePass<'_>, |
505 | 122 | ) -> Result<(), Error> { |
506 | 122 | let shape = PropertyShape::from(platform_properties); |
507 | 122 | let (observation, fails_actions) = { |
508 | 122 | let mut tracker = pass.tracker.lock(); |
509 | 122 | let observation = tracker.observe( |
510 | 122 | shape.clone(), |
511 | 122 | pass.now, |
512 | 122 | pass.fleet_generation, |
513 | 122 | insert_timestamp, |
514 | 122 | ); |
515 | 122 | (observation, tracker.fails_actions()) |
516 | 122 | }; |
517 | 122 | if observation.should_warn { |
518 | | // Without a timeout nothing is failed, and a pool that |
519 | | // scales up from zero shows up here on every cold start. |
520 | 43 | if fails_actions { |
521 | 38 | warn!( |
522 | | %reason, |
523 | 38 | waited_s = observation.waited.as_secs(), |
524 | | "Queued action cannot run on any connected worker" |
525 | | ); |
526 | | } else { |
527 | 5 | info!( |
528 | | %reason, |
529 | 5 | waited_s = observation.waited.as_secs(), |
530 | | "Queued action cannot run on any connected worker" |
531 | | ); |
532 | | } |
533 | 79 | } |
534 | 122 | if !observation.is_due { |
535 | 80 | return Ok(()); |
536 | 42 | } |
537 | | // The action must also have waited the timeout itself, so one that |
538 | | // arrives while its shape is already due is not failed on sight. |
539 | | // Actions queued together still fail within about one timeout; |
540 | | // during a pool outage later actions fail as they age instead of |
541 | | // in an immediate burst. The tracker wakes the loop when it does. |
542 | 42 | if !observation.action_eligible { |
543 | 14 | return Ok(()); |
544 | 28 | } |
545 | | // A worker that joined here or on a peer since the pass began may |
546 | | // be able to run it, so leave it for the next pass to judge. |
547 | 28 | if workers.fleet_generation().await != pass.fleet_generation { |
548 | 0 | return Ok(()); |
549 | 28 | } |
550 | | |
551 | | // Blast-radius cap: fail at most `cap` actions per pass. Over-cap |
552 | | // actions were still observed above (their timers keep running) and |
553 | | // are reconsidered next pass, so a large burst bleeds off over a few |
554 | | // back-to-back passes rather than failing all at once. |
555 | 28 | if pass.fails_this_pass.load(Ordering::Relaxed) >= pass.cap { |
556 | 0 | return Ok(()); |
557 | 28 | } |
558 | 28 | pass.fails_this_pass.fetch_add(1, Ordering::Relaxed); |
559 | | |
560 | 28 | let operation_id = { |
561 | 28 | let (action_state, _origin_metadata) = action_state_result |
562 | 28 | .as_state() |
563 | 28 | .await |
564 | 28 | .err_tip(|| "Failed to get state of an unsatisfiable action")?0 ; |
565 | 28 | action_state.client_operation_id.clone() |
566 | | }; |
567 | | // The client only hears what it asked for; what workers offer |
568 | | // stays in the server log above. |
569 | 28 | let err = make_err!( |
570 | 28 | Code::FailedPrecondition, |
571 | | "Action cannot be scheduled, {}. No capable worker has been connected for {}s.", |
572 | 28 | reason.for_client(), |
573 | 28 | observation.waited.as_secs() |
574 | | ); |
575 | 28 | let failed = matching_engine_state_manager |
576 | 28 | .fail_queued_operation(&operation_id, err) |
577 | 28 | .await |
578 | 28 | .err_tip(|| "Failed to fail an unsatisfiable action in do_try_match")?0 ; |
579 | 28 | if failed { |
580 | 28 | record_unsatisfiable_failed(reason.property_names()); |
581 | 28 | // So a pass that retires every eligible action of the shape |
582 | 28 | // does not read as stuck and back off the next wake. |
583 | 28 | pass.tracker.lock().note_failed(&shape); |
584 | 28 | }0 |
585 | 28 | Ok(()) |
586 | 122 | } |
587 | | |
588 | | /// A listed action with what matching needs of it. |
589 | | struct Loaded { |
590 | | action_state_result: Box<dyn ActionStateResult>, |
591 | | action_info: ActionInfoWithProps, |
592 | | } |
593 | | |
594 | | /// Reads what matching needs of a listed action. `None` when the |
595 | | /// record cannot be read: gone from the store (eviction), or |
596 | | /// unreadable. Counted so an operator can see the store losing |
597 | | /// records, skipped so the rest of the pass still runs, and not an |
598 | | /// error, since an error here made the pass rerun at once and log |
599 | | /// ten times a second until the entry went away. |
600 | 589 | async fn load_action( |
601 | 589 | action_state_result: Box<dyn ActionStateResult>, |
602 | 589 | platform_property_manager: &PlatformPropertyManager, |
603 | 589 | typed_properties: &Mutex<HashMap<u64, PlatformProperties>>, |
604 | 589 | ) -> Result<Option<Loaded>, Error> { |
605 | 588 | let (action_info, maybe_origin_metadata) = |
606 | 589 | match action_state_result.as_action_info().await { |
607 | 588 | Ok(found) => found, |
608 | 1 | Err(err0 ) if is_lost_record(&err)0 => { |
609 | 0 | if err.code == Code::NotFound { |
610 | 0 | debug!( |
611 | | ?err, |
612 | | "Queued operation listed but its record is gone; skipping" |
613 | | ); |
614 | | } else { |
615 | 0 | warn!( |
616 | | ?err, |
617 | | "Queued operation listed but its record cannot be read; skipping" |
618 | | ); |
619 | | } |
620 | 0 | record_awaited_action_orphan("matching"); |
621 | 0 | return Ok(None); |
622 | | } |
623 | | // The store itself failed, so the pass is incomplete: |
624 | | // an error here reruns it at once, as before. |
625 | 1 | Err(err) => { |
626 | 1 | return Err(err).err_tip( |
627 | | || "Failed to get action info in SimpleScheduler::do_try_match", |
628 | | ); |
629 | | } |
630 | | }; |
631 | | |
632 | 588 | let platform_properties = typed_properties_for( |
633 | 588 | typed_properties, |
634 | 588 | platform_property_manager, |
635 | 588 | &action_info.platform_properties, |
636 | | ) |
637 | 588 | .err_tip(|| "Failed to make platform properties in SimpleScheduler::do_try_match")?0 ; |
638 | | |
639 | 588 | Ok(Some(Loaded { |
640 | 588 | action_state_result, |
641 | 588 | action_info: ActionInfoWithProps { |
642 | 588 | inner: action_info, |
643 | 588 | platform_properties, |
644 | 588 | origin_metadata: maybe_origin_metadata.unwrap_or_default(), |
645 | 588 | scheduler_start_execute_event_id: None, |
646 | 588 | }, |
647 | 588 | })) |
648 | 589 | } |
649 | | |
650 | | /// What became of a dispatch that did not fail. |
651 | | #[derive(Clone, Copy, PartialEq, Eq)] |
652 | | enum Dispatch { |
653 | | /// The worker was told to run the action. |
654 | | Sent, |
655 | | /// Another scheduler assigned the action first; nothing was sent. |
656 | | LostRace, |
657 | | } |
658 | | |
659 | | /// Hands a matched action to its worker. `Ok(Dispatch::Sent)` means |
660 | | /// the worker was actually told; a lost assignment race is not an |
661 | | /// error but sends nothing. |
662 | 228 | async fn dispatch_to_worker( |
663 | 228 | action_state_result: &dyn ActionStateResult, |
664 | 228 | workers: &ApiWorkerScheduler, |
665 | 228 | matching_engine_state_manager: &dyn MatchingEngineStateManager, |
666 | 228 | maybe_origin_event_tx: Option<&mpsc::Sender<OriginEvent>>, |
667 | 228 | worker_id: WorkerId, |
668 | 228 | action_info: ActionInfoWithProps, |
669 | 228 | now_fn: &(dyn Fn() -> SystemTime + Send + Sync), |
670 | 228 | ) -> Result<Dispatch, Error> { |
671 | 228 | let origin_metadata = action_info.origin_metadata.clone(); |
672 | 228 | let event_origin_metadata = origin_metadata.clone(); |
673 | 228 | let attach_operation_fut = async move { |
674 | | // Extract the operation_id from the action_state. |
675 | 228 | let operation_id = { |
676 | 228 | let (action_state, _origin_metadata) = action_state_result |
677 | 228 | .as_state() |
678 | 228 | .await |
679 | 228 | .err_tip(|| "Failed to get action_info from as_state_result stream")?0 ; |
680 | 228 | action_state.client_operation_id.clone() |
681 | | }; |
682 | | |
683 | | // Tell the matching engine that the operation is being assigned to a worker. |
684 | 228 | let assign_result = matching_engine_state_manager |
685 | 228 | .assign_operation(&operation_id, Ok(&worker_id)) |
686 | 228 | .await |
687 | 228 | .err_tip(|| "Failed to assign operation in do_try_match"); |
688 | 228 | if let Err(err10 ) = assign_result { |
689 | 10 | if err.code == Code::Aborted { |
690 | | // If the operation was aborted, it means that the operation was |
691 | | // cancelled due to another operation being assigned to the worker. |
692 | 9 | return Ok(Dispatch::LostRace); |
693 | 1 | } |
694 | | // Any other error is a real error. |
695 | 1 | return Err(err); |
696 | 218 | } |
697 | | |
698 | 218 | let mut action_info = action_info; |
699 | 218 | let scheduler_start_execute_event = maybe_origin_event_tx.map(|_| {1 |
700 | 1 | let event = SimpleScheduler::scheduler_start_execute_event( |
701 | 1 | &worker_id, |
702 | 1 | &operation_id, |
703 | 1 | &action_info, |
704 | | ); |
705 | 1 | let event_id = SimpleScheduler::origin_event_id(&event); |
706 | 1 | action_info.scheduler_start_execute_event_id = Some(event_id.clone()); |
707 | 1 | (event_id, event) |
708 | 1 | }); |
709 | | |
710 | 218 | debug!(%worker_id, %operation_id, ?action_info, "Notifying worker of operation"); |
711 | 218 | let dispatched_at = now_fn() |
712 | 218 | .duration_since(UNIX_EPOCH) |
713 | 218 | .unwrap_or_default() |
714 | 218 | .as_secs(); |
715 | 218 | workers |
716 | 218 | .worker_notify_run_action(worker_id, operation_id, action_info, dispatched_at) |
717 | 218 | .await |
718 | 218 | .err_tip(|| {1 |
719 | 1 | "Failed to run worker_notify_run_action in SimpleScheduler::do_try_match" |
720 | 1 | })?; |
721 | | |
722 | 217 | if let Some((event_id1 , event1 )) = scheduler_start_execute_event { |
723 | 1 | SimpleScheduler::publish_scheduler_start_execute( |
724 | 1 | maybe_origin_event_tx, |
725 | 1 | &event_origin_metadata, |
726 | 1 | event_id, |
727 | 1 | event, |
728 | 1 | ) |
729 | 1 | .await; |
730 | 216 | } |
731 | | |
732 | 217 | Ok(Dispatch::Sent) |
733 | 228 | }; |
734 | 228 | tokio::pin!(attach_operation_fut); |
735 | | |
736 | 228 | let ctx = Context::current_with_baggage(vec![KeyValue::new( |
737 | | ENDUSER_ID, |
738 | 228 | origin_metadata.identity, |
739 | | )]); |
740 | | |
741 | 228 | info_span!("do_try_match") |
742 | 228 | .in_scope(|| attach_operation_fut) |
743 | 228 | .with_context(ctx) |
744 | 228 | .await |
745 | 228 | } |
746 | | |
747 | | /// Actions this pass read that found no room, in the order the |
748 | | /// queue listed them: highest priority first, then oldest. That is |
749 | | /// the order room is offered to them in, before the action the |
750 | | /// pass is reading, whenever the fleet's capacity changes. Parking |
751 | | /// is a push; a replay walks the list once and asks the fleet once |
752 | | /// per property shape it meets, since every action of one shape |
753 | | /// asks the same of a worker: a shape whose first parked action |
754 | | /// finds no room is skipped for the rest of that replay. |
755 | | #[derive(Default)] |
756 | | struct Parked { |
757 | | /// Each with its shape, computed once at parking. |
758 | | queue: VecDeque<(PropertyShape, Loaded)>, |
759 | | /// Actions that were not parked because the list was full. |
760 | | cap_dropped: u64, |
761 | | } |
762 | | |
763 | | /// Past this many parked actions a pass stops parking, so a newer |
764 | | /// action past that point may take room ahead of one of them. The |
765 | | /// head of the queue, which is what a client waits on, is always |
766 | | /// parked. |
767 | | const PARKED_CAP: usize = 10_000; |
768 | | |
769 | | impl Parked { |
770 | 211 | fn park(&mut self, loaded: Loaded) { |
771 | 211 | if self.queue.len() >= PARKED_CAP { |
772 | 0 | self.cap_dropped += 1; |
773 | 0 | return; |
774 | 211 | } |
775 | 211 | let shape = PropertyShape::from(&loaded.action_info.platform_properties); |
776 | 211 | self.queue.push_back((shape, loaded)); |
777 | 211 | } |
778 | | |
779 | 864 | fn is_empty(&self) -> bool { |
780 | 864 | self.queue.is_empty() |
781 | 864 | } |
782 | | } |
783 | | |
784 | | /// What one pass did with its parked actions. |
785 | | #[derive(Default)] |
786 | | struct Placement { |
787 | | /// Parked actions that found a worker and were dispatched to it. |
788 | | attempted: u64, |
789 | | /// Of those, the ones the worker was actually told to run. |
790 | | dispatched: u64, |
791 | | /// Of those, the ones another scheduler assigned first. |
792 | | lost_race: u64, |
793 | | /// Of those, the ones whose dispatch failed. |
794 | | failed: u64, |
795 | | } |
796 | | |
797 | | /// Offers the room that opened since the pass last looked to the |
798 | | /// parked actions in listing order. Every parked action that found |
799 | | /// a worker leaves the list, whatever its dispatch came to. |
800 | | #[expect(clippy::too_many_arguments)] |
801 | 4 | async fn place_parked( |
802 | 4 | parked: &mut Parked, |
803 | 4 | placement: &mut Placement, |
804 | 4 | contended: &mut HashSet<PropertyShape>, |
805 | 4 | workers: &ApiWorkerScheduler, |
806 | 4 | matching_engine_state_manager: &dyn MatchingEngineStateManager, |
807 | 4 | maybe_origin_event_tx: Option<&mpsc::Sender<OriginEvent>>, |
808 | 4 | full_worker_logging: bool, |
809 | 4 | now: SystemTime, |
810 | 4 | now_fn: &(dyn Fn() -> SystemTime + Send + Sync), |
811 | 4 | ) -> Result<(), Error> { |
812 | 4 | let mut result = Ok(()); |
813 | 4 | let mut blocked: HashSet<PropertyShape> = HashSet::new(); |
814 | 4 | let mut still_parked = VecDeque::with_capacity(parked.queue.len()); |
815 | 11 | while let Some((shape7 , loaded7 )) = parked.queue.pop_front() { |
816 | 7 | if blocked.contains(&shape) || contended.contains(&shape) { |
817 | 1 | still_parked.push_back((shape, loaded)); |
818 | 1 | continue; |
819 | 6 | } |
820 | 6 | let MatchOutcome::Matched(worker_id5 ) = workers |
821 | 6 | .find_worker_for_action( |
822 | 6 | &loaded.action_info.platform_properties, |
823 | 6 | full_worker_logging, |
824 | 6 | now, |
825 | 6 | Some(QueuedAction { |
826 | 6 | unique_qualifier: &loaded.action_info.inner.unique_qualifier, |
827 | 6 | insert_timestamp: loaded.action_info.inner.insert_timestamp, |
828 | 6 | }), |
829 | | ) |
830 | 6 | .await |
831 | | else { |
832 | 1 | still_parked.push_back((shape.clone(), loaded)); |
833 | 1 | blocked.insert(shape); |
834 | 1 | continue; |
835 | | }; |
836 | 5 | placement.attempted += 1; |
837 | 5 | match dispatch_to_worker( |
838 | 5 | loaded.action_state_result.as_ref(), |
839 | 5 | workers, |
840 | 5 | matching_engine_state_manager, |
841 | 5 | maybe_origin_event_tx, |
842 | 5 | worker_id, |
843 | 5 | loaded.action_info, |
844 | 5 | now_fn, |
845 | | ) |
846 | 5 | .await |
847 | | { |
848 | 4 | Ok(Dispatch::Sent) => placement.dispatched += 1, |
849 | 1 | Ok(Dispatch::LostRace) => { |
850 | 1 | placement.lost_race += 1; |
851 | 1 | contended.insert(shape); |
852 | 1 | } |
853 | 0 | Err(err) => { |
854 | 0 | placement.failed += 1; |
855 | 0 | result = result.merge(Err(err)); |
856 | 0 | } |
857 | | } |
858 | | } |
859 | 4 | parked.queue = still_parked; |
860 | 4 | result |
861 | 4 | } |
862 | | |
863 | 864 | let mut result = Ok(()); |
864 | | |
865 | 864 | let start = Instant::now(); |
866 | | |
867 | 864 | let unsatisfiable_pass = UnsatisfiablePass { |
868 | 864 | tracker: &self.unsatisfiable_tracker, |
869 | 864 | now: (self.now_fn)(), |
870 | 864 | fleet_generation: self.worker_scheduler.fleet_generation().await, |
871 | 864 | cap: unsatisfiable_fail_cap(self.last_unsatisfiable_backlog.load(Ordering::Relaxed)), |
872 | 864 | fails_this_pass: AtomicUsize::new(0), |
873 | | }; |
874 | | // With no worker connected anywhere and the no-worker timeout set, |
875 | | // every queued action is judged by that clock instead. A fleet the |
876 | | // census cannot vouch for counts as having workers. |
877 | 864 | let no_worker_pass = match &self.no_worker_tracker10 { |
878 | 10 | Some(tracker) |
879 | 10 | if self |
880 | 10 | .worker_scheduler |
881 | 10 | .no_worker_anywhere(unsatisfiable_pass.now) |
882 | 7 | .await => |
883 | | { |
884 | 7 | Some(UnsatisfiablePass { |
885 | 7 | tracker, |
886 | 7 | now: unsatisfiable_pass.now, |
887 | 7 | fleet_generation: unsatisfiable_pass.fleet_generation, |
888 | 7 | cap: unsatisfiable_pass.cap, |
889 | 7 | fails_this_pass: AtomicUsize::new(0), |
890 | 7 | }) |
891 | | } |
892 | 857 | _ => None, |
893 | | }; |
894 | 864 | let no_workers_reason = UnsatisfiableReason::no_workers(); |
895 | | |
896 | 864 | let mut stream861 = self |
897 | 864 | .get_queued_operations() |
898 | 864 | .await |
899 | 861 | .err_tip(|| "Failed to get queued operations in do_try_match")?0 ; |
900 | | |
901 | 861 | let query_elapsed = start.elapsed(); |
902 | 861 | if query_elapsed > Duration::from_secs(1) { |
903 | 0 | warn!( |
904 | 0 | elapsed_ms = query_elapsed.as_millis(), |
905 | | "Slow get_queued_operations query" |
906 | | ); |
907 | 861 | } |
908 | | |
909 | 861 | let workers = self.worker_scheduler.as_ref(); |
910 | 861 | let matching_engine_state_manager = self.matching_engine_state_manager.as_ref(); |
911 | 861 | let maybe_origin_event_tx = self.maybe_origin_event_tx.as_ref(); |
912 | 861 | let mut parked = Parked::default(); |
913 | 861 | let mut placement = Placement::default(); |
914 | | // Once a peer wins an assignment, let it advance through that |
915 | | // property shape for this pass. Other shapes can still use this |
916 | | // scheduler's workers, and the next pass tries every shape again. |
917 | 861 | let mut contended = HashSet::new(); |
918 | 861 | let mut oldest_queued = Vec::new(); |
919 | 861 | let hold_pass = workers.begin_pass_holds().await; |
920 | 861 | let mut capacity_seen = workers.capacity_generation(); |
921 | 861 | let mut queued_seen: u64 = 0; |
922 | | // How long each action read has waited since its client submitted |
923 | | // it, requeues included: the pass already reads every queued action, |
924 | | // so the ages cost nothing more from the store. |
925 | 861 | let mut queued_ages = AgeBuckets::default(); |
926 | 1.45k | 'actions: while let Some(action_state_result589 ) = stream.next().await { |
927 | 589 | queued_seen += 1; |
928 | 589 | let loaded588 = match load_action( |
929 | 589 | action_state_result, |
930 | 589 | self.platform_property_manager.as_ref(), |
931 | 589 | &self.typed_properties, |
932 | | ) |
933 | 589 | .await |
934 | | { |
935 | 588 | Ok(Some(loaded)) => loaded, |
936 | 0 | Ok(None) => continue, |
937 | 1 | Err(err) => { |
938 | 1 | result = result.merge(Err(err)); |
939 | 1 | continue; |
940 | | } |
941 | | }; |
942 | 588 | queued_ages.observe_since( |
943 | 588 | loaded.action_info.inner.insert_timestamp, |
944 | 588 | unsatisfiable_pass.now, |
945 | | ); |
946 | 588 | if full_worker_logging { |
947 | 148 | oldest_queued.push(loaded.action_info.inner.clone()); |
948 | 148 | oldest_queued.sort_unstable_by_key(|action| action102 .insert_timestamp); |
949 | 148 | oldest_queued.truncate(5); |
950 | 440 | } |
951 | 588 | let shape = PropertyShape::from(&loaded.action_info.platform_properties); |
952 | 588 | if contended.contains(&shape) { |
953 | 1 | continue; |
954 | 587 | } |
955 | | |
956 | | // Room that opened since the pass last placed anything belongs |
957 | | // to the oldest action still waiting, not to this one, which is |
958 | | // newer than everything parked. The generation is read under the |
959 | | // placement lock, so a change cannot slip between the two. |
960 | 587 | let outcome = loop { |
961 | 591 | let (outcome, generation) = workers |
962 | 591 | .find_worker_for_action_observed( |
963 | 591 | &loaded.action_info.platform_properties, |
964 | 591 | full_worker_logging, |
965 | 591 | unsatisfiable_pass.now, |
966 | 591 | Some(QueuedAction { |
967 | 591 | unique_qualifier: &loaded.action_info.inner.unique_qualifier, |
968 | 591 | insert_timestamp: loaded.action_info.inner.insert_timestamp, |
969 | 591 | }), |
970 | | ) |
971 | 591 | .await; |
972 | 591 | if generation == capacity_seen || parked5 .is_empty5 () { |
973 | 587 | capacity_seen = generation; |
974 | 587 | break outcome; |
975 | 4 | } |
976 | 4 | capacity_seen = generation; |
977 | 4 | result = result.merge( |
978 | 4 | place_parked( |
979 | 4 | &mut parked, |
980 | 4 | &mut placement, |
981 | 4 | &mut contended, |
982 | 4 | workers, |
983 | 4 | matching_engine_state_manager, |
984 | 4 | maybe_origin_event_tx, |
985 | 4 | full_worker_logging, |
986 | 4 | unsatisfiable_pass.now, |
987 | 4 | self.now_fn.as_ref(), |
988 | 4 | ) |
989 | 4 | .await, |
990 | | ); |
991 | 4 | if contended.contains(&shape) { |
992 | 0 | continue 'actions; |
993 | 4 | } |
994 | | }; |
995 | | |
996 | 587 | match outcome { |
997 | 223 | MatchOutcome::Matched(worker_id) => { |
998 | 223 | result = result.merge( |
999 | 223 | dispatch_to_worker( |
1000 | 223 | loaded.action_state_result.as_ref(), |
1001 | 223 | workers, |
1002 | 223 | matching_engine_state_manager, |
1003 | 223 | maybe_origin_event_tx, |
1004 | 223 | worker_id, |
1005 | 223 | loaded.action_info, |
1006 | 223 | self.now_fn.as_ref(), |
1007 | 223 | ) |
1008 | 223 | .await |
1009 | 223 | .map(|dispatch| {221 |
1010 | 221 | if dispatch == Dispatch::LostRace { |
1011 | 8 | contended.insert(shape); |
1012 | 213 | } |
1013 | 221 | }), |
1014 | | ); |
1015 | | } |
1016 | | // A worker could run it once one has room. The match |
1017 | | // considered holding a worker for it (`reservation_hold`). |
1018 | 211 | MatchOutcome::WaitingForCapacity => { |
1019 | 211 | parked.park(loaded); |
1020 | 211 | } |
1021 | | // Nothing to wait for; a worker connecting starts a new pass, |
1022 | | // unless the no-worker clock is running. |
1023 | | MatchOutcome::NoWorkersConnected => { |
1024 | 38 | if let Some(no_worker_pass7 ) = &no_worker_pass { |
1025 | 7 | result = result.merge( |
1026 | 7 | handle_unsatisfiable( |
1027 | 7 | loaded.action_state_result.as_ref(), |
1028 | 7 | matching_engine_state_manager, |
1029 | 7 | workers, |
1030 | 7 | &loaded.action_info.platform_properties, |
1031 | 7 | loaded.action_info.inner.insert_timestamp, |
1032 | 7 | &no_workers_reason, |
1033 | 7 | no_worker_pass, |
1034 | 7 | ) |
1035 | 7 | .await, |
1036 | | ); |
1037 | 31 | } |
1038 | | } |
1039 | 115 | MatchOutcome::Unsatisfiable(reason) => { |
1040 | 115 | result = result.merge( |
1041 | 115 | handle_unsatisfiable( |
1042 | 115 | loaded.action_state_result.as_ref(), |
1043 | 115 | matching_engine_state_manager, |
1044 | 115 | workers, |
1045 | 115 | &loaded.action_info.platform_properties, |
1046 | 115 | loaded.action_info.inner.insert_timestamp, |
1047 | 115 | &reason, |
1048 | 115 | &unsatisfiable_pass, |
1049 | 115 | ) |
1050 | 115 | .await, |
1051 | | ); |
1052 | | } |
1053 | | } |
1054 | | } |
1055 | | // Room that opened after the last action was read. |
1056 | 859 | if !parked.is_empty() && workers168 .capacity_generation() != capacity_seen { |
1057 | 0 | result = result.merge( |
1058 | 0 | place_parked( |
1059 | 0 | &mut parked, |
1060 | 0 | &mut placement, |
1061 | 0 | &mut contended, |
1062 | 0 | workers, |
1063 | 0 | matching_engine_state_manager, |
1064 | 0 | maybe_origin_event_tx, |
1065 | 0 | full_worker_logging, |
1066 | 0 | unsatisfiable_pass.now, |
1067 | 0 | self.now_fn.as_ref(), |
1068 | 0 | ) |
1069 | 0 | .await, |
1070 | | ); |
1071 | 859 | } |
1072 | | // The whole queue was read: a held action the pass did not meet |
1073 | | // is gone, and a hold past its time is given up. |
1074 | 859 | workers |
1075 | 859 | .end_pass_holds(hold_pass, unsatisfiable_pass.now) |
1076 | 859 | .await; |
1077 | 859 | record_parked_dispatched(placement.dispatched); |
1078 | 859 | if placement.attempted > 0 || parked.cap_dropped > 0855 { |
1079 | 4 | debug!( |
1080 | | attempted = placement.attempted, |
1081 | | dispatched = placement.dispatched, |
1082 | | lost_race = placement.lost_race, |
1083 | | failed = placement.failed, |
1084 | | cap_dropped = parked.cap_dropped, |
1085 | 4 | still_parked = parked.queue.len(), |
1086 | 4 | elapsed_ms = start.elapsed().as_millis(), |
1087 | | "Parked actions offered the room that opened mid-pass" |
1088 | | ); |
1089 | 855 | } |
1090 | | |
1091 | 859 | let mut unsatisfiable_queued = self |
1092 | 859 | .unsatisfiable_tracker |
1093 | 859 | .lock() |
1094 | 859 | .end_pass(unsatisfiable_pass.now, unsatisfiable_pass.fleet_generation); |
1095 | 859 | if let Some(tracker10 ) = &self.no_worker_tracker { |
1096 | 10 | unsatisfiable_queued += tracker |
1097 | 10 | .lock() |
1098 | 10 | .end_pass(unsatisfiable_pass.now, unsatisfiable_pass.fleet_generation); |
1099 | 849 | } |
1100 | 859 | record_unsatisfiable_queued(unsatisfiable_queued); |
1101 | 859 | record_queue_depth(queued_seen); |
1102 | 859 | record_queue_ages(&queued_ages); |
1103 | 859 | if full_worker_logging { |
1104 | 140 | let actions: Vec<_> = oldest_queued |
1105 | 140 | .iter() |
1106 | 148 | .map140 (|action| (&action.unique_qualifier, action.insert_timestamp)) |
1107 | 140 | .collect(); |
1108 | 140 | info!(?actions, queued_seen, "Oldest actions in the matching pass"); |
1109 | 719 | } |
1110 | | // Remember this pass's backlog so the next pass can size its fail cap: |
1111 | | // a large backlog lets more of it drain per pass (unsatisfiable_fail_cap). |
1112 | 859 | self.last_unsatisfiable_backlog.store( |
1113 | 859 | usize::try_from(unsatisfiable_queued).unwrap_or(usize::MAX), |
1114 | 859 | Ordering::Relaxed, |
1115 | | ); |
1116 | | |
1117 | 859 | let total_elapsed = start.elapsed(); |
1118 | 859 | if total_elapsed > Duration::from_secs(5) { |
1119 | 0 | warn!( |
1120 | 0 | total_ms = total_elapsed.as_millis(), |
1121 | 0 | query_ms = query_elapsed.as_millis(), |
1122 | | "Slow do_try_match cycle" |
1123 | | ); |
1124 | 859 | } |
1125 | | |
1126 | 859 | result |
1127 | 859 | } |
1128 | | } |
1129 | | |
1130 | | impl SimpleScheduler { |
1131 | 1 | pub fn new<A: AwaitedActionDb>( |
1132 | 1 | spec: &SimpleSpec, |
1133 | 1 | awaited_action_db: A, |
1134 | 1 | task_change_notify: Arc<Notify>, |
1135 | 1 | maybe_origin_event_tx: Option<mpsc::Sender<OriginEvent>>, |
1136 | 1 | ) -> (Arc<Self>, Arc<dyn WorkerScheduler>) { |
1137 | 1 | Self::new_with_callback( |
1138 | 1 | spec, |
1139 | 1 | awaited_action_db, |
1140 | 0 | || { |
1141 | | // The cost of running `do_try_match()` is very high, but constant |
1142 | | // in relation to the number of changes that have happened. This |
1143 | | // means that grabbing this lock to process `do_try_match()` should |
1144 | | // always yield to any other tasks that might want the lock. The |
1145 | | // easiest and most fair way to do this is to sleep for a small |
1146 | | // amount of time. Using something like tokio::task::yield_now() |
1147 | | // does not yield as aggressively as we'd like if new futures are |
1148 | | // scheduled within a future. |
1149 | 0 | tokio::time::sleep(Duration::from_millis(1)) |
1150 | 0 | }, |
1151 | 1 | task_change_notify, |
1152 | | SystemTime::now, |
1153 | 1 | maybe_origin_event_tx, |
1154 | | ) |
1155 | 1 | } |
1156 | | |
1157 | 113 | pub fn new_with_callback< |
1158 | 113 | Fut: Future<Output = ()> + Send, |
1159 | 113 | F: Fn() -> Fut + Send + Sync + 'static, |
1160 | 113 | A: AwaitedActionDb, |
1161 | 113 | I: InstantWrapper, |
1162 | 113 | NowFn: Fn() -> I + Clone + Send + Unpin + Sync + 'static, |
1163 | 113 | >( |
1164 | 113 | spec: &SimpleSpec, |
1165 | 113 | awaited_action_db: A, |
1166 | 113 | on_matching_engine_run: F, |
1167 | 113 | task_change_notify: Arc<Notify>, |
1168 | 113 | now_fn: NowFn, |
1169 | 113 | maybe_origin_event_tx: Option<mpsc::Sender<OriginEvent>>, |
1170 | 113 | ) -> (Arc<Self>, Arc<dyn WorkerScheduler>) { |
1171 | 113 | Self::new_with_fleet_exchange_interval( |
1172 | 113 | spec, |
1173 | 113 | awaited_action_db, |
1174 | 113 | on_matching_engine_run, |
1175 | 113 | task_change_notify, |
1176 | 113 | now_fn, |
1177 | 113 | maybe_origin_event_tx, |
1178 | | FLEET_EXCHANGE_INTERVAL, |
1179 | | ) |
1180 | 113 | } |
1181 | | |
1182 | | /// Same as `new_with_callback`, with the interval at which worker |
1183 | | /// capabilities are swapped with peer schedulers, so a test need not wait |
1184 | | /// out the real one. |
1185 | 115 | pub fn new_with_fleet_exchange_interval< |
1186 | 115 | Fut: Future<Output = ()> + Send, |
1187 | 115 | F: Fn() -> Fut + Send + Sync + 'static, |
1188 | 115 | A: AwaitedActionDb, |
1189 | 115 | I: InstantWrapper, |
1190 | 115 | NowFn: Fn() -> I + Clone + Send + Unpin + Sync + 'static, |
1191 | 115 | >( |
1192 | 115 | spec: &SimpleSpec, |
1193 | 115 | mut awaited_action_db: A, |
1194 | 115 | on_matching_engine_run: F, |
1195 | 115 | task_change_notify: Arc<Notify>, |
1196 | 115 | now_fn: NowFn, |
1197 | 115 | maybe_origin_event_tx: Option<mpsc::Sender<OriginEvent>>, |
1198 | 115 | fleet_exchange_interval: Duration, |
1199 | 115 | ) -> (Arc<Self>, Arc<dyn WorkerScheduler>) { |
1200 | 115 | let platform_property_manager = Arc::new(PlatformPropertyManager::new( |
1201 | 115 | spec.supported_platform_properties |
1202 | 115 | .clone() |
1203 | 115 | .unwrap_or_default(), |
1204 | | )); |
1205 | | |
1206 | 115 | let mut worker_timeout_s = spec.worker_timeout_s; |
1207 | 115 | if worker_timeout_s == 0 { |
1208 | 108 | worker_timeout_s = DEFAULT_WORKER_TIMEOUT_S; |
1209 | 108 | }7 |
1210 | | |
1211 | 115 | let mut client_action_timeout_s = spec.client_action_timeout_s; |
1212 | 115 | if client_action_timeout_s == 0 { |
1213 | 67 | client_action_timeout_s = DEFAULT_CLIENT_ACTION_TIMEOUT_S; |
1214 | 67 | }48 |
1215 | | // This matches the value of CLIENT_KEEPALIVE_DURATION which means that |
1216 | | // tasks are going to be dropped all over the place, this isn't a good |
1217 | | // setting. |
1218 | 115 | if client_action_timeout_s <= CLIENT_KEEPALIVE_DURATION.as_secs() { |
1219 | 0 | error!( |
1220 | | client_action_timeout_s, |
1221 | | "Setting client_action_timeout_s to less than the client keep alive interval is going to cause issues, please set above {}.", |
1222 | 0 | CLIENT_KEEPALIVE_DURATION.as_secs() |
1223 | | ); |
1224 | 115 | } |
1225 | | |
1226 | 115 | let mut max_job_retries = spec.max_job_retries; |
1227 | 115 | if max_job_retries == 0 { |
1228 | 100 | max_job_retries = DEFAULT_MAX_JOB_RETRIES; |
1229 | 100 | }15 |
1230 | | |
1231 | 115 | let mut unacknowledged_kill_timeout_s = spec.unacknowledged_kill_timeout_s; |
1232 | 115 | if unacknowledged_kill_timeout_s == 0 { |
1233 | 115 | unacknowledged_kill_timeout_s = DEFAULT_UNACKNOWLEDGED_KILL_TIMEOUT_S; |
1234 | 115 | }0 |
1235 | | |
1236 | 115 | let worker_change_notify = Arc::new(Notify::new()); |
1237 | | |
1238 | | // Create shared worker registry for single heartbeat per worker. |
1239 | 115 | let worker_registry = Arc::new(WorkerRegistry::new()); |
1240 | | |
1241 | | // The db decides on its own whether an executing action was abandoned, |
1242 | | // so it needs the same liveness view the state manager uses. |
1243 | 115 | awaited_action_db.set_worker_registry(worker_registry.clone()); |
1244 | | |
1245 | 115 | let unsatisfiable_action_timeout = match spec.unsatisfiable_action_timeout_s { |
1246 | 89 | 0 => None, |
1247 | 26 | secs => Some(Duration::from_secs(secs)), |
1248 | | }; |
1249 | 115 | let no_worker_action_timeout = match spec.no_worker_action_timeout_s { |
1250 | 113 | 0 => None, |
1251 | 2 | secs => Some(Duration::from_secs(secs)), |
1252 | | }; |
1253 | 115 | let scheduler_now_fn = { |
1254 | 115 | let now_fn = now_fn.clone(); |
1255 | 1.91k | Box::new115 (move || now_fn().now()) |
1256 | | }; |
1257 | | // A second SystemTime clock for the fleet-exchange task, cloned before |
1258 | | // `now_fn` is moved into the state manager below. |
1259 | 115 | let exchange_now_fn: Box<dyn Fn() -> SystemTime + Send + Sync> = { |
1260 | 115 | let now_fn = now_fn.clone(); |
1261 | 115 | Box::new(move || now_fn()52 .now52 ()) |
1262 | | }; |
1263 | | // One peer-record TTL: the fleet-exchange record's lifetime and the |
1264 | | // census warm-up / staleness bound the worker scheduler applies. |
1265 | 115 | let record_ttl = fleet_exchange_interval * FLEET_RECORD_TTL_INTERVALS; |
1266 | | |
1267 | 115 | let has_peers = awaited_action_db.shares_state(); |
1268 | 115 | let retry_limits = RetryLimits { |
1269 | 115 | max_job_retries, |
1270 | 115 | max_worker_loss_retries: if spec.max_worker_loss_retries == 0 { |
1271 | 109 | RetryLimits::DEFAULT_WORKER_LOSS_RETRIES |
1272 | | } else { |
1273 | 6 | spec.max_worker_loss_retries |
1274 | | }, |
1275 | 115 | max_escalations: spec.memory_escalation.as_ref().map_or(0, |policy| {5 |
1276 | 5 | usize::try_from(policy.max_steps).unwrap_or(usize::MAX) |
1277 | 5 | }), |
1278 | | }; |
1279 | 115 | let state_manager = SimpleSchedulerStateManager::new( |
1280 | 115 | retry_limits, |
1281 | 115 | Duration::from_secs(worker_timeout_s), |
1282 | 115 | Duration::from_secs(client_action_timeout_s), |
1283 | 115 | Duration::from_secs(spec.max_action_executing_timeout_s), |
1284 | 115 | awaited_action_db, |
1285 | 115 | now_fn, |
1286 | 115 | Some(worker_registry.clone()), |
1287 | | ); |
1288 | | |
1289 | | // The id this scheduler publishes its fleet to its peers under, and |
1290 | | // takes its turn holding workers by. |
1291 | 115 | let scheduler_id = Uuid::new_v4().hyphenated().to_string(); |
1292 | 115 | let worker_scheduler = ApiWorkerScheduler::new( |
1293 | 115 | state_manager.clone(), |
1294 | 115 | platform_property_manager.clone(), |
1295 | 115 | spec.allocation_strategy, |
1296 | 115 | spec.live_memory_veto.clone(), |
1297 | 115 | spec.memory_escalation.clone(), |
1298 | 115 | spec.reservation_hold, |
1299 | 115 | worker_change_notify.clone(), |
1300 | 115 | worker_timeout_s, |
1301 | 115 | unacknowledged_kill_timeout_s, |
1302 | 115 | spec.dispatch_ack_timeout_s, |
1303 | 115 | worker_registry, |
1304 | 115 | maybe_origin_event_tx.clone(), |
1305 | 115 | has_peers, |
1306 | 115 | record_ttl, |
1307 | 115 | scheduler_id.clone(), |
1308 | | ); |
1309 | | |
1310 | 115 | let worker_scheduler_clone = worker_scheduler.clone(); |
1311 | | |
1312 | 115 | let fallback_match_interval = match spec.fallback_match_interval_s { |
1313 | | // Zero or any negative value means disabled. |
1314 | 115 | ..=0 => None113 , |
1315 | 2 | secs => Some(Duration::from_secs(secs.unsigned_abs())), |
1316 | | }; |
1317 | | |
1318 | | // Retiring abandoned queued actions is its own task rather than part |
1319 | | // of the matching pass. The matching pass is exactly what stops |
1320 | | // running when they pile up, so making the cleanup depend on it |
1321 | | // means the cleanup stops precisely when it is needed. Sweeping on |
1322 | | // the client timeout bounds how long one can sit there to roughly |
1323 | | // twice that. |
1324 | 115 | let sweep_interval = Duration::from_secs(client_action_timeout_s); |
1325 | 115 | let sweep_state_manager = Arc::downgrade(&state_manager); |
1326 | 115 | let task_abandoned_sweep_spawn = |
1327 | 115 | spawn!("simple_scheduler_task_abandoned_sweep", async move {108 |
1328 | | loop { |
1329 | 108 | tokio::time::sleep(sweep_interval).await; |
1330 | | // Weak, so the sweep stops when the scheduler goes away. |
1331 | 0 | let Some(state_manager) = sweep_state_manager.upgrade() else { |
1332 | 0 | return; |
1333 | | }; |
1334 | 0 | if let Err(err) = state_manager.sweep_abandoned_queued_actions().await { |
1335 | 0 | record_sweep_failure(); |
1336 | 0 | error!(?err, "Error while sweeping abandoned queued actions"); |
1337 | 0 | } |
1338 | | } |
1339 | 0 | }); |
1340 | | |
1341 | | // Executing actions get their own sweep for the same reason, on the |
1342 | | // scheduler's clock rather than a waiting client's. |
1343 | 115 | let executing_sweep_interval = match spec.executing_sweep_interval_s { |
1344 | 115 | ..=0 => None, |
1345 | 0 | secs => Some(Duration::from_secs(secs.unsigned_abs())), |
1346 | | }; |
1347 | | // Disabled means no task at all, not a task that returns at once. |
1348 | 115 | let task_executing_sweep_spawn = executing_sweep_interval.map(|interval| {0 |
1349 | 0 | let state_manager = Arc::downgrade(&state_manager); |
1350 | 0 | let worker_scheduler = Arc::downgrade(&worker_scheduler); |
1351 | 0 | spawn!("simple_scheduler_task_executing_sweep", async move { |
1352 | | // Long enough that an assignment's store write and the |
1353 | | // dispatch behind it are never mistaken for a lost result. |
1354 | 0 | let lost_grace = (interval * 2).max(Duration::from_mins(1)); |
1355 | 0 | let mut lost_since = HashMap::new(); |
1356 | | loop { |
1357 | 0 | tokio::time::sleep(interval).await; |
1358 | 0 | let (Some(state_manager), Some(worker_scheduler)) = |
1359 | 0 | (state_manager.upgrade(), worker_scheduler.upgrade()) |
1360 | | else { |
1361 | | // Only on process shutdown, when the scheduler that |
1362 | | // owned this task is gone; worth a line if it ever |
1363 | | // happens any other way. |
1364 | 0 | info!("Scheduler dropped, stopping the executing sweep"); |
1365 | 0 | return; |
1366 | | }; |
1367 | 0 | let check_scheduler = worker_scheduler.clone(); |
1368 | 0 | let running_on_worker = |
1369 | 0 | move |worker_id: WorkerId, operation_id: OperationId| { |
1370 | 0 | let worker_scheduler = check_scheduler.clone(); |
1371 | 0 | async move { |
1372 | 0 | worker_scheduler |
1373 | 0 | .running_on_worker(&worker_id, &operation_id) |
1374 | 0 | .await |
1375 | 0 | } |
1376 | 0 | .boxed() |
1377 | 0 | }; |
1378 | 0 | match state_manager |
1379 | 0 | .sweep_executing_actions(&running_on_worker, &mut lost_since, lost_grace) |
1380 | 0 | .await |
1381 | | { |
1382 | 0 | Ok(report) => { |
1383 | 0 | record_executing_ages(&report.ages); |
1384 | 0 | if report.retired + report.requeued + report.failed > 0 { |
1385 | 0 | info!( |
1386 | | retired = report.retired, |
1387 | | requeued = report.requeued, |
1388 | | failed = report.failed, |
1389 | | "Executing sweep" |
1390 | | ); |
1391 | 0 | } |
1392 | | } |
1393 | 0 | Err(err) => { |
1394 | 0 | record_sweep_failure(); |
1395 | 0 | error!(?err, "Error while sweeping executing actions"); |
1396 | | } |
1397 | | } |
1398 | 0 | drop((state_manager, worker_scheduler)); |
1399 | | } |
1400 | 0 | }) |
1401 | 0 | }); |
1402 | | |
1403 | | // Only runs when the state is shared. It runs whatever the timeout, |
1404 | | // so that a peer which does fail actions sees these workers even |
1405 | | // while this scheduler is still rolling out or has the timeout off. |
1406 | 115 | let task_fleet_exchange_spawn = { |
1407 | 115 | let state_manager = Arc::downgrade(&state_manager); |
1408 | 115 | let local_fleet_change_notify = worker_scheduler.local_fleet_change_notify().clone(); |
1409 | 115 | let worker_scheduler = Arc::downgrade(&worker_scheduler); |
1410 | 115 | spawn!("simple_scheduler_task_fleet_exchange", async move {108 |
1411 | 108 | if !has_peers { |
1412 | 104 | return; |
1413 | 4 | } |
1414 | 4 | let mut last_exchange_ok = true; |
1415 | | loop { |
1416 | 52 | let (Some(state_manager), Some(worker_scheduler)) = |
1417 | 52 | (state_manager.upgrade(), worker_scheduler.upgrade()) |
1418 | | else { |
1419 | 0 | return; |
1420 | | }; |
1421 | 52 | let local = worker_scheduler.fleet_shapes().await; |
1422 | 52 | match state_manager |
1423 | 52 | .exchange_fleet_capabilities(&scheduler_id, local, record_ttl) |
1424 | 52 | .await |
1425 | | { |
1426 | 52 | Ok(peer_fleet) => { |
1427 | 52 | if !last_exchange_ok { |
1428 | 0 | info!("Exchanging fleet capabilities with peer schedulers again"); |
1429 | 52 | } |
1430 | 52 | last_exchange_ok = true; |
1431 | 52 | worker_scheduler |
1432 | 52 | .set_peer_fleet(Some(peer_fleet), exchange_now_fn()) |
1433 | 52 | .await; |
1434 | | } |
1435 | 0 | Err(err) => { |
1436 | | // A peer that cannot be seen might have a worker |
1437 | | // for any action, so no action is judged |
1438 | | // unsatisfiable until the peers can be read again. |
1439 | 0 | if last_exchange_ok { |
1440 | 0 | warn!( |
1441 | | ?err, |
1442 | | "Could not exchange fleet capabilities with peer schedulers, no queued action is failed as unsatisfiable until this recovers" |
1443 | | ); |
1444 | 0 | } |
1445 | 0 | last_exchange_ok = false; |
1446 | 0 | worker_scheduler |
1447 | 0 | .set_peer_fleet(None, exchange_now_fn()) |
1448 | 0 | .await; |
1449 | | } |
1450 | | } |
1451 | 52 | drop((state_manager, worker_scheduler)); |
1452 | | // A worker joining or leaving here is published straight |
1453 | | // away, so peers see it within one of their intervals. |
1454 | 52 | tokio::select! { |
1455 | 52 | () = tokio::time::sleep(fleet_exchange_interval) => {}35 |
1456 | 52 | () = local_fleet_change_notify.notified() => {}13 |
1457 | | } |
1458 | | } |
1459 | 104 | }) |
1460 | | }; |
1461 | | |
1462 | 115 | let action_scheduler = Arc::new_cyclic(move |weak_self| -> Self { |
1463 | 115 | let weak_inner = weak_self.clone(); |
1464 | 115 | let task_worker_matching_spawn = |
1465 | 115 | spawn!("simple_scheduler_task_worker_matching", async move {108 |
1466 | 108 | let mut last_match_successful = true; |
1467 | 108 | let mut worker_match_logging_last: Option<Instant> = None; |
1468 | | // Break out of the loop only when the inner is dropped. |
1469 | | loop { |
1470 | 823 | let task_change_fut = task_change_notify.notified(); |
1471 | 823 | let worker_change_fut = worker_change_notify.notified(); |
1472 | 823 | tokio::pin!(task_change_fut); |
1473 | 823 | tokio::pin!(worker_change_fut); |
1474 | | // Wait for either of these futures to be ready. |
1475 | 823 | let state_changed = future::select(task_change_fut, worker_change_fut); |
1476 | 823 | let max_wait = if last_match_successful { |
1477 | | // Even on success, periodically re-run the match as a |
1478 | | // fallback for missed notifications and eventually |
1479 | | // consistent backends (e.g. a re-queued operation that |
1480 | | // was not yet visible to the search triggered by its |
1481 | | // own notification). Without this, such an operation |
1482 | | // can stay queued until an unrelated event triggers |
1483 | | // another matching pass. |
1484 | 822 | fallback_match_interval |
1485 | | } else { |
1486 | | // If the last match failed, then run again after a short sleep. |
1487 | | // This resolves issues where we tried to re-schedule a job to |
1488 | | // a disconnected worker. The sleep ensures we don't enter a |
1489 | | // hard loop if there's something wrong inside do_try_match. |
1490 | 1 | Some(Duration::from_millis(100)) |
1491 | | }; |
1492 | | // Wake in time to fail actions no worker can run, |
1493 | | // even when nothing else triggers a pass. |
1494 | 823 | let unsatisfiable_deadline = weak_inner.upgrade().and_then(|scheduler| { |
1495 | 823 | let now = (scheduler.now_fn)(); |
1496 | 823 | scheduler.unsatisfiable_deadline(now) |
1497 | 823 | }); |
1498 | 823 | let max_wait = match (max_wait, unsatisfiable_deadline) { |
1499 | 1 | (Some(max_wait), Some(deadline)) => Some(max_wait.min(deadline)), |
1500 | 822 | (max_wait, deadline) => max_wait.or(deadline), |
1501 | | }; |
1502 | 823 | if let Some(max_wait38 ) = max_wait { |
1503 | 38 | let sleep_fut = tokio::time::sleep(max_wait); |
1504 | 38 | tokio::pin!(sleep_fut); |
1505 | 38 | let _ = future::select(state_changed, sleep_fut).await; |
1506 | | } else { |
1507 | 785 | let _ = state_changed.await; |
1508 | | } |
1509 | | |
1510 | 720 | let result715 = match weak_inner.upgrade() { |
1511 | 720 | Some(scheduler) => { |
1512 | 720 | let now = Instant::now(); |
1513 | 720 | let full_worker_logging = { |
1514 | 720 | match scheduler.worker_match_logging_interval { |
1515 | 712 | None => false, |
1516 | 8 | Some(duration) => match worker_match_logging_last { |
1517 | 3 | None => true, |
1518 | 5 | Some(when) => now.duration_since(when) >= duration, |
1519 | | }, |
1520 | | } |
1521 | | }; |
1522 | | |
1523 | 720 | let res715 = scheduler.do_try_match(full_worker_logging).await; |
1524 | 715 | if full_worker_logging { |
1525 | 3 | worker_match_logging_last.replace(now); |
1526 | 712 | } |
1527 | 715 | res |
1528 | | } |
1529 | | // If the inner went away it means the scheduler is shutting |
1530 | | // down, so we need to resolve our future. |
1531 | 0 | None => return, |
1532 | | }; |
1533 | 715 | last_match_successful = result.is_ok(); |
1534 | 715 | if let Err(err1 ) = result { |
1535 | 1 | error!(?err, "Error while running do_try_match"); |
1536 | 714 | } |
1537 | | |
1538 | 715 | on_matching_engine_run().await; |
1539 | | } |
1540 | | // Unreachable. |
1541 | 0 | }); |
1542 | | |
1543 | 115 | let worker_match_logging_interval = match spec.worker_match_logging_interval_s { |
1544 | | // -1 or 0 means disabled (0 used to cause expensive logging on every call) |
1545 | 111 | -1 | 0 => None, |
1546 | 4 | signed_secs => { |
1547 | 4 | if let Ok(secs3 ) = TryInto::<u64>::try_into(signed_secs) { |
1548 | 3 | Some(Duration::from_secs(secs)) |
1549 | | } else { |
1550 | 1 | error!( |
1551 | | worker_match_logging_interval_s = spec.worker_match_logging_interval_s, |
1552 | | "Valid values for worker_match_logging_interval_s are -1, 0, or a positive integer, setting to disabled", |
1553 | | ); |
1554 | 1 | None |
1555 | | } |
1556 | | } |
1557 | | }; |
1558 | | Self { |
1559 | 115 | matching_engine_state_manager: state_manager.clone(), |
1560 | 115 | client_state_manager: state_manager.clone(), |
1561 | 115 | worker_scheduler, |
1562 | 115 | platform_property_manager, |
1563 | 115 | maybe_origin_event_tx, |
1564 | 115 | task_worker_matching_spawn, |
1565 | 115 | task_abandoned_sweep_spawn, |
1566 | 115 | task_executing_sweep_spawn, |
1567 | 115 | task_fleet_exchange_spawn, |
1568 | 115 | worker_match_logging_interval, |
1569 | 115 | typed_properties: Mutex::new(HashMap::new()), |
1570 | 115 | unsatisfiable_tracker: Mutex::new(UnsatisfiableTracker::new( |
1571 | 115 | unsatisfiable_action_timeout, |
1572 | | )), |
1573 | 115 | no_worker_tracker: no_worker_action_timeout |
1574 | 115 | .map(|timeout| Mutex::new2 (UnsatisfiableTracker::new2 (Some(timeout)2 ))), |
1575 | 115 | last_unsatisfiable_backlog: AtomicUsize::new(0), |
1576 | 115 | now_fn: scheduler_now_fn, |
1577 | | } |
1578 | 115 | }); |
1579 | 115 | (action_scheduler, worker_scheduler_clone) |
1580 | 115 | } |
1581 | | } |
1582 | | |
1583 | | #[async_trait] |
1584 | | impl ClientStateManager for SimpleScheduler { |
1585 | | async fn add_action( |
1586 | | &self, |
1587 | | client_operation_id: OperationId, |
1588 | | action_info: Arc<ActionInfo>, |
1589 | 255 | ) -> Result<Box<dyn ActionStateResult>, Error> { |
1590 | | self.inner_add_action(client_operation_id, action_info) |
1591 | | .await |
1592 | 255 | } |
1593 | | |
1594 | | async fn filter_operations<'a>( |
1595 | | &'a self, |
1596 | | filter: OperationFilter, |
1597 | 512 | ) -> Result<ActionStateResultStream<'a>, Error> { |
1598 | | self.inner_filter_operations(filter).await |
1599 | 512 | } |
1600 | | } |
1601 | | |
1602 | | #[async_trait] |
1603 | | impl KnownPlatformPropertyProvider for SimpleScheduler { |
1604 | 0 | async fn get_known_properties(&self, _instance_name: &str) -> Result<Vec<String>, Error> { |
1605 | | Ok(self |
1606 | | .worker_scheduler |
1607 | | .get_platform_property_manager() |
1608 | | .get_known_properties() |
1609 | | .keys() |
1610 | | .cloned() |
1611 | | .collect()) |
1612 | 0 | } |
1613 | | } |
1614 | | |
1615 | | #[async_trait] |
1616 | | impl WorkerScheduler for SimpleScheduler { |
1617 | 0 | fn get_platform_property_manager(&self) -> &PlatformPropertyManager { |
1618 | 0 | self.worker_scheduler.get_platform_property_manager() |
1619 | 0 | } |
1620 | | |
1621 | 150 | async fn add_worker(&self, worker: Worker) -> Result<(), Error> { |
1622 | | self.worker_scheduler.add_worker(worker).await |
1623 | 150 | } |
1624 | | |
1625 | | async fn worker_dispatch_accepted( |
1626 | | &self, |
1627 | | worker_id: &WorkerId, |
1628 | | operation_id: &OperationId, |
1629 | 3 | ) -> Result<(), Error> { |
1630 | | self.worker_scheduler |
1631 | | .worker_dispatch_accepted(worker_id, operation_id) |
1632 | | .await |
1633 | 3 | } |
1634 | | |
1635 | | async fn worker_dispatch_declined( |
1636 | | &self, |
1637 | | worker_id: &WorkerId, |
1638 | | operation_id: &OperationId, |
1639 | | reason: String, |
1640 | | needs_kb: Option<u64>, |
1641 | 3 | ) -> Result<(), Error> { |
1642 | | self.worker_scheduler |
1643 | | .worker_dispatch_declined(worker_id, operation_id, reason, needs_kb) |
1644 | | .await |
1645 | 3 | } |
1646 | | |
1647 | | async fn update_action( |
1648 | | &self, |
1649 | | worker_id: &WorkerId, |
1650 | | operation_id: &OperationId, |
1651 | | update: UpdateOperationType, |
1652 | 30 | ) -> Result<(), Error> { |
1653 | | self.worker_scheduler |
1654 | | .update_action(worker_id, operation_id, update) |
1655 | | .await |
1656 | 30 | } |
1657 | | |
1658 | | async fn worker_keep_alive_received( |
1659 | | &self, |
1660 | | worker_id: &WorkerId, |
1661 | | timestamp: WorkerTimestamp, |
1662 | | load: Option<WorkerLoad>, |
1663 | 16 | ) -> Result<(), Error> { |
1664 | | self.worker_scheduler |
1665 | | .worker_keep_alive_received(worker_id, timestamp, load) |
1666 | | .await |
1667 | 16 | } |
1668 | | |
1669 | | async fn worker_running_operations_reported( |
1670 | | &self, |
1671 | | worker_id: &WorkerId, |
1672 | | operation_ids: Vec<OperationId>, |
1673 | 0 | ) -> Result<(), Error> { |
1674 | | self.worker_scheduler |
1675 | | .worker_running_operations_reported(worker_id, operation_ids) |
1676 | | .await |
1677 | 0 | } |
1678 | | |
1679 | | async fn worker_liveness_refreshed( |
1680 | | &self, |
1681 | | worker_id: &WorkerId, |
1682 | | timestamp: WorkerTimestamp, |
1683 | 0 | ) -> Result<(), Error> { |
1684 | | self.worker_scheduler |
1685 | | .worker_liveness_refreshed(worker_id, timestamp) |
1686 | | .await |
1687 | 0 | } |
1688 | | |
1689 | 10 | async fn remove_worker(&self, worker_id: &WorkerId) -> Result<(), Error> { |
1690 | | self.worker_scheduler.remove_worker(worker_id).await |
1691 | 10 | } |
1692 | | |
1693 | 0 | async fn worker_disconnected(&self, worker_id: &WorkerId) -> Result<(), Error> { |
1694 | | self.worker_scheduler.worker_disconnected(worker_id).await |
1695 | 0 | } |
1696 | | |
1697 | 0 | async fn shutdown(&self, shutdown_guard: ShutdownGuard) { |
1698 | | self.worker_scheduler.shutdown(shutdown_guard).await; |
1699 | 0 | } |
1700 | | |
1701 | 3 | async fn remove_timedout_workers(&self, now_timestamp: WorkerTimestamp) -> Result<(), Error> { |
1702 | | self.worker_scheduler |
1703 | | .remove_timedout_workers(now_timestamp) |
1704 | | .await |
1705 | 3 | } |
1706 | | |
1707 | 3 | async fn set_drain_worker(&self, worker_id: &WorkerId, is_draining: bool) -> Result<(), Error> { |
1708 | | self.worker_scheduler |
1709 | | .set_drain_worker(worker_id, is_draining) |
1710 | | .await |
1711 | 3 | } |
1712 | | |
1713 | 2 | async fn worker_snapshot(&self) -> Vec<WorkerSummary> { |
1714 | | self.worker_scheduler.worker_snapshot().await |
1715 | 2 | } |
1716 | | |
1717 | 7 | async fn kill_revoked_operations(&self) -> Result<(), Error> { |
1718 | | self.worker_scheduler.kill_revoked_operations().await |
1719 | 7 | } |
1720 | | } |
1721 | | |
1722 | | impl RootMetricsComponent for SimpleScheduler {} |
1723 | | |
1724 | | #[cfg(test)] |
1725 | | mod unsatisfiable_fail_cap_tests { |
1726 | | use super::{ |
1727 | | MAX_UNSATISFIABLE_FAILS_PER_PASS, UNSATISFIABLE_FAIL_BACKLOG_DIVISOR, |
1728 | | unsatisfiable_fail_cap, |
1729 | | }; |
1730 | | |
1731 | | #[test] |
1732 | 1 | fn small_backlog_stays_at_the_floor() { |
1733 | | // Zero and any backlog whose fraction is below the floor use the floor. |
1734 | 1 | assert_eq!(unsatisfiable_fail_cap(0), MAX_UNSATISFIABLE_FAILS_PER_PASS); |
1735 | 1 | assert_eq!(unsatisfiable_fail_cap(20), MAX_UNSATISFIABLE_FAILS_PER_PASS); |
1736 | | // Exactly at the boundary (floor * divisor) still yields the floor. |
1737 | 1 | let boundary = MAX_UNSATISFIABLE_FAILS_PER_PASS * UNSATISFIABLE_FAIL_BACKLOG_DIVISOR; |
1738 | 1 | assert_eq!( |
1739 | 1 | unsatisfiable_fail_cap(boundary), |
1740 | | MAX_UNSATISFIABLE_FAILS_PER_PASS |
1741 | | ); |
1742 | 1 | } |
1743 | | |
1744 | | #[test] |
1745 | 1 | fn large_backlog_scales_to_drain_in_a_few_passes() { |
1746 | | // A big burst drains in ~DIVISOR back-to-back passes. |
1747 | 1 | assert_eq!( |
1748 | 1 | unsatisfiable_fail_cap(4000), |
1749 | 1 | 4000 / UNSATISFIABLE_FAIL_BACKLOG_DIVISOR |
1750 | | ); |
1751 | | // Just past the boundary crosses over to the fraction. |
1752 | 1 | let over = MAX_UNSATISFIABLE_FAILS_PER_PASS * UNSATISFIABLE_FAIL_BACKLOG_DIVISOR |
1753 | 1 | + UNSATISFIABLE_FAIL_BACKLOG_DIVISOR; |
1754 | 1 | assert!(unsatisfiable_fail_cap(over) > MAX_UNSATISFIABLE_FAILS_PER_PASS); |
1755 | 1 | } |
1756 | | } |