1mod emu;
29mod timers;
30
31use crate::emu::EmulationTimerOps;
32use anyhow::{Context, Result};
33use async_trait::async_trait;
34use fidl::encoding::ProxyChannelBox;
35use fidl::endpoints::RequestStream;
36use fidl_fuchsia_driver_token as fdt;
37use fidl_fuchsia_hardware_hrtimer as ffhh;
38use fidl_fuchsia_time_alarms as fta;
39use fuchsia_async as fasync;
40use fuchsia_component::client::Service;
41use fuchsia_inspect as finspect;
42use fuchsia_inspect::{IntProperty, NumericProperty, Property};
43use fuchsia_runtime as fxr;
44use fuchsia_trace as trace;
45use futures::StreamExt;
46use futures::channel::mpsc;
47use futures::sink::SinkExt;
48use log::{debug, error, warn};
49use scopeguard::defer;
50use std::cell::RefCell;
51use std::num::NonZeroUsize;
52use std::rc::Rc;
53use std::sync::LazyLock;
54use time_pretty::{MSEC_IN_NANOS, format_duration, format_timer};
55use zx::AsHandleRef;
56
57static DEBUG_STACK_TRACE_TOKEN: std::sync::OnceLock<zx::Event> = std::sync::OnceLock::new();
58static I64_MAX_AS_U64: LazyLock<u64> = LazyLock::new(|| i64::MAX.try_into().expect("infallible"));
59static I32_MAX_AS_U64: LazyLock<u64> = LazyLock::new(|| i32::MAX.try_into().expect("infallible"));
60
61static MAX_USEFUL_TICKS: LazyLock<u64> = LazyLock::new(|| *I32_MAX_AS_U64);
63
64static MIN_USEFUL_TICKS: u64 = 1;
68
69const MAIN_TIMER_ID: usize = 6;
72
73const LONG_DELAY_NANOS: i64 = 2000 * MSEC_IN_NANOS;
75
76const TIMEOUT_SECONDS: i64 = 40;
77
78async fn request_stack_trace() {
79 if let Some(ev) = DEBUG_STACK_TRACE_TOKEN.get() {
80 log::warn!("*** DRIVER STACK TRACE REQUESTED: expect a driver stack trace below.");
81 let ev_dup = ev.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap();
82 let debug_proxy = fuchsia_component::client::connect_to_protocol::<fdt::DebugMarker>();
83 match debug_proxy {
84 Ok(proxy) => {
85 if let Err(e) = proxy.log_stack_trace(ev_dup).await {
86 log::warn!("failed to log stack trace: {:?}", e);
87 }
88 }
89 Err(e) => {
90 log::warn!("failed to connect to Debug protocol: {:?}", e);
91 }
92 }
93 } else {
94 log::warn!("DEBUG_STACK_TRACE_TOKEN not initialized, cannot log stack trace");
95 }
96}
97
98macro_rules! log_long_op {
101 ($fut:expr) => {{
102 use futures::FutureExt;
103 let fut = $fut;
104 futures::pin_mut!(fut);
105 let mut logged = false;
106 loop {
107 let timeout = fasync::Timer::new(zx::MonotonicDuration::from_seconds(TIMEOUT_SECONDS));
108 futures::select! {
109 res = fut.as_mut().fuse() => {
110 if logged {
111 log::warn!("unexpected blocking is now resolved: long-running async operation at {}:{}.",
112 file!(), line!());
113 }
114 break res;
115 }
116 _ = timeout.fuse() => {
117 log::warn!("unexpected blocking: long-running async op at {}:{}. Report to `componentId:1408151`",
119 file!(), line!());
120 if !logged {
121 #[cfg(all(target_os = "fuchsia", not(doc)))]
122 ::debug::backtrace_request_all_threads();
123 fasync::Task::local(request_stack_trace()).detach();
124 }
125 logged = true;
126 }
127 }
128 }
129 }};
130}
131
132struct ScopedInc<'a> {
134 property: &'a IntProperty,
135}
136
137impl<'a> ScopedInc<'a> {
138 fn new(property: &'a IntProperty) -> Self {
139 property.add(1);
140 Self { property }
141 }
142}
143
144impl<'a> Drop for ScopedInc<'a> {
145 fn drop(&mut self) {
146 self.property.add(-1);
147 }
148}
149
150fn is_deadline_changed(
153 before: Option<fasync::BootInstant>,
154 after: Option<fasync::BootInstant>,
155) -> bool {
156 match (before, after) {
157 (None, None) => false,
158 (None, Some(_)) | (Some(_), None) => true,
159 (Some(before), Some(after)) => before != after,
160 }
161}
162
163#[derive(Debug, Clone)]
165pub(crate) enum TimerOpsError {
166 Driver(ffhh::DriverError),
168 Fidl(fidl::Error),
170}
171
172impl Into<fta::WakeAlarmsError> for TimerOpsError {
173 fn into(self) -> fta::WakeAlarmsError {
176 match self {
177 TimerOpsError::Fidl(fidl::Error::ClientChannelClosed { .. }) => {
178 fta::WakeAlarmsError::DriverConnection
179 }
180 TimerOpsError::Driver(ffhh::DriverError::InternalError) => fta::WakeAlarmsError::Driver,
181 _ => fta::WakeAlarmsError::Internal,
182 }
183 }
184}
185
186impl TimerOpsError {
187 fn is_canceled(&self) -> bool {
188 match self {
189 TimerOpsError::Driver(ffhh::DriverError::Canceled) => true,
190 _ => false,
191 }
192 }
193}
194
195trait SawResponseFut: std::future::Future<Output = Result<zx::EventPair, TimerOpsError>> {
196 }
198
199#[async_trait(?Send)]
201pub(crate) trait TimerOps {
202 async fn stop(&self, id: u64);
204
205 async fn get_timer_properties(&self) -> TimerConfig;
208
209 fn start_and_wait(
214 &self,
215 id: u64,
216 resolution: &ffhh::Resolution,
217 ticks: u64,
218 setup_event: zx::Event,
219 ) -> std::pin::Pin<Box<dyn SawResponseFut>>;
220}
221
222struct HardwareTimerOps {
224 proxy: ffhh::DeviceProxy,
225}
226
227impl HardwareTimerOps {
228 fn new(proxy: ffhh::DeviceProxy) -> Box<Self> {
229 Box::new(Self { proxy })
230 }
231}
232
233#[async_trait(?Send)]
234impl TimerOps for HardwareTimerOps {
235 async fn stop(&self, id: u64) {
236 let _ = self
237 .proxy
238 .stop(id)
239 .await
240 .map(|result| {
241 let _ = result.map_err(|e| warn!("stop_hrtimer: driver error: {:?}", e));
242 })
243 .map_err(|e| warn!("stop_hrtimer: could not stop prior timer: {}", e));
244 }
245
246 async fn get_timer_properties(&self) -> TimerConfig {
247 match log_long_op!(self.proxy.get_properties()) {
248 Ok(p) => {
249 if let Some(token) = p.driver_node_token {
250 let _ = DEBUG_STACK_TRACE_TOKEN.set(token);
251 }
252 let timers_properties = &p.timers_properties.expect("timers_properties must exist");
253 debug!("get_timer_properties: got: {:?}", timers_properties);
254
255 let timer_index = if timers_properties.len() > MAIN_TIMER_ID {
257 MAIN_TIMER_ID
260 } else if timers_properties.len() > 0 {
261 0
265 } else {
266 return TimerConfig::new_empty();
268 };
269 let main_timer_properties = &timers_properties[timer_index];
270 debug!("alarms: main_timer_properties: {:?}", main_timer_properties);
271 let max_ticks: u64 = std::cmp::min(
273 main_timer_properties.max_ticks.unwrap_or(*MAX_USEFUL_TICKS),
274 *MAX_USEFUL_TICKS,
275 );
276 let resolutions = &main_timer_properties
277 .supported_resolutions
278 .as_ref()
279 .expect("supported_resolutions is populated")
280 .iter()
281 .last() .map(|r| match *r {
283 ffhh::Resolution::Duration(d) => d,
284 _ => {
285 error!(
286 "get_timer_properties: Unknown resolution type, returning millisecond."
287 );
288 MSEC_IN_NANOS
289 }
290 })
291 .map(|d| zx::BootDuration::from_nanos(d))
292 .into_iter() .collect::<Vec<_>>();
294 let timer_id = main_timer_properties.id.expect("timer ID is always present");
295 TimerConfig::new_from_data(timer_id, resolutions, max_ticks)
296 }
297 Err(e) => {
298 error!("could not get timer properties: {:?}", e);
299 TimerConfig::new_empty()
300 }
301 }
302 }
303
304 fn start_and_wait(
305 &self,
306 id: u64,
307 resolution: &ffhh::Resolution,
308 ticks: u64,
309 setup_event: zx::Event,
310 ) -> std::pin::Pin<Box<dyn SawResponseFut>> {
311 let inner = self.proxy.start_and_wait(id, resolution, ticks, setup_event);
312 Box::pin(HwResponseFut { pinner: Box::pin(inner) })
313 }
314}
315
316struct HwResponseFut {
319 pinner: std::pin::Pin<
320 Box<
321 fidl::client::QueryResponseFut<
322 ffhh::DeviceStartAndWaitResult,
323 fidl::encoding::DefaultFuchsiaResourceDialect,
324 >,
325 >,
326 >,
327}
328
329use std::task::Poll;
330impl SawResponseFut for HwResponseFut {}
331impl std::future::Future for HwResponseFut {
332 type Output = Result<zx::EventPair, TimerOpsError>;
333 fn poll(
334 mut self: std::pin::Pin<&mut Self>,
335 cx: &mut std::task::Context<'_>,
336 ) -> std::task::Poll<Self::Output> {
337 let inner_poll = self.pinner.as_mut().poll(cx);
338 match inner_poll {
339 Poll::Ready(result) => Poll::Ready(match result {
340 Ok(Ok(keep_alive)) => Ok(keep_alive),
341 Ok(Err(e)) => Err(TimerOpsError::Driver(e)),
342 Err(e) => Err(TimerOpsError::Fidl(e)),
343 }),
344 Poll::Pending => Poll::Pending,
345 }
346 }
347}
348
349async fn stop_hrtimer(hrtimer: &Box<dyn TimerOps>, timer_config: &TimerConfig) {
351 trace::duration!("alarms", "hrtimer:stop", "id" => timer_config.id);
352 debug!("stop_hrtimer: stopping hardware timer: {}", timer_config.id);
353 log_long_op!(hrtimer.stop(timer_config.id));
354 debug!("stop_hrtimer: stopped hardware timer: {}", timer_config.id);
355}
356
357const CHANNEL_SIZE: usize = 1000;
360
361#[derive(Debug)]
363enum Cmd {
364 Start {
366 conn_id: zx::Koid,
368 deadline: timers::Deadline,
370 mode: Option<fta::SetMode>,
379 alarm_id: String,
381 responder: Rc<dyn timers::Responder>,
389 },
390 StopById {
391 done: zx::Event,
392 timer_id: timers::Id,
393 },
394 Alarm {
395 expired_deadline: fasync::BootInstant,
396 keep_alive: fidl::EventPair,
397 },
398 AlarmFidlError {
399 expired_deadline: fasync::BootInstant,
400 error: fidl::Error,
401 },
402 AlarmDriverError {
403 expired_deadline: fasync::BootInstant,
404 error: ffhh::DriverError,
405
406 timer_config_id: u64,
408 resolution_nanos: i64,
409 ticks: u64,
410 },
411 UtcUpdated {
413 transform: fxr::UtcClockTransform,
415 },
416}
417
418impl std::fmt::Display for Cmd {
419 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
420 match self {
421 Cmd::Start { conn_id, deadline, alarm_id, .. } => {
422 write!(
423 f,
424 "Start[alarm_id=\"{}\", conn_id={:?}, deadline={}]",
425 alarm_id, conn_id, deadline,
426 )
427 }
428 Cmd::Alarm { expired_deadline, .. } => {
429 write!(f, "Alarm[deadline={}]", format_timer((*expired_deadline).into()))
430 }
431 Cmd::AlarmFidlError { expired_deadline, error } => {
432 write!(
433 f,
434 "FIDLError[deadline={}, err={}, NO_WAKE_LEASE!]",
435 format_timer((*expired_deadline).into()),
436 error
437 )
438 }
439 Cmd::AlarmDriverError { expired_deadline, error, .. } => {
440 write!(
441 f,
442 "DriverError[deadline={}, err={:?}, NO_WAKE_LEASE!]",
443 format_timer((*expired_deadline).into()),
444 error
445 )
446 }
447 Cmd::StopById { timer_id, done: _ } => {
448 write!(f, "StopById[timerId={}]", timer_id,)
449 }
450 Cmd::UtcUpdated { transform } => {
451 write!(f, "UtcUpdated[timerId={transform:?}]")
452 }
453 }
454 }
455}
456
457pub fn get_stream_koid(
470 stream: fta::WakeAlarmsRequestStream,
471) -> (zx::Koid, fta::WakeAlarmsRequestStream) {
472 let (inner, is_terminated) = stream.into_inner();
473 let koid = inner.channel().as_channel().as_handle_ref().koid().expect("infallible");
474 let stream = fta::WakeAlarmsRequestStream::from_inner(inner, is_terminated);
475 (koid, stream)
476}
477
478pub async fn serve(timer_loop: Rc<Loop>, requests: fta::WakeAlarmsRequestStream) {
488 let timer_loop = timer_loop.clone();
489 let timer_loop_send = || timer_loop.get_sender();
490 let (conn_id, mut requests) = get_stream_koid(requests);
491 let mut request_count = 0;
492 debug!("alarms::serve: opened connection: {:?}", conn_id);
493 while let Some(maybe_request) = requests.next().await {
494 request_count += 1;
495 debug!("alarms::serve: conn_id: {:?} incoming request: {}", conn_id, request_count);
496 match maybe_request {
497 Ok(request) => {
498 handle_request(conn_id, timer_loop_send(), request).await;
500 }
501 Err(e) => {
502 warn!("alarms::serve: error in request: {:?}", e);
503 }
504 }
505 debug!("alarms::serve: conn_id: {:?} done request: {}", conn_id, request_count);
506 }
507 warn!("alarms::serve: CLOSED CONNECTION: conn_id: {:?}", conn_id);
510}
511
512async fn handle_cancel(alarm_id: String, conn_id: zx::Koid, cmd: &mut mpsc::Sender<Cmd>) {
513 let done = zx::Event::create();
514 let timer_id = timers::Id::new(alarm_id.clone(), conn_id);
515 if let Err(e) = log_long_op!(cmd.send(Cmd::StopById {
516 timer_id,
517 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible"),
518 })) {
519 warn!("handle_request: error while trying to cancel: {}: {:?}", alarm_id, e);
520 }
521 log_long_op!(wait_signaled(&done));
522}
523
524async fn handle_request(
532 conn_id: zx::Koid,
533 mut cmd: mpsc::Sender<Cmd>,
534 request: fta::WakeAlarmsRequest,
535) {
536 match request {
537 fta::WakeAlarmsRequest::SetAndWait { deadline, mode, alarm_id, responder } => {
538 let responder = Rc::new(RefCell::new(Some(responder)));
548
549 debug!(
551 "handle_request: scheduling alarm_id: \"{}\"\n\tconn_id: {:?}\n\tdeadline: {}",
552 alarm_id,
553 conn_id,
554 format_timer(deadline.into())
555 );
556 let deadline = timers::Deadline::Boot(deadline.into());
558 if let Err(e) = log_long_op!(cmd.send(Cmd::Start {
559 conn_id,
560 deadline,
561 mode: Some(mode),
562 alarm_id: alarm_id.clone(),
563 responder: responder.clone(),
564 })) {
565 warn!("handle_request: error while trying to schedule `{}`: {:?}", alarm_id, e);
566 responder
567 .borrow_mut()
568 .take()
569 .expect("always present if call fails")
570 .send(Err(fta::WakeAlarmsError::Internal))
571 .unwrap();
572 }
573 }
574 fta::WakeAlarmsRequest::SetAndWaitUtc { deadline, mode, alarm_id, responder } => {
575 let deadline =
577 timers::Deadline::Utc(fxr::UtcInstant::from_nanos(deadline.timestamp_utc));
578
579 let responder = Rc::new(RefCell::new(Some(responder)));
582 debug!(
583 "handle_request: scheduling alarm_id UTC: \"{alarm_id}\"\n\tconn_id: {conn_id:?}\n\tdeadline: {deadline}",
584 );
585
586 if let Err(e) = log_long_op!(cmd.send(Cmd::Start {
587 conn_id,
588 deadline,
589 mode: Some(mode),
590 alarm_id: alarm_id.clone(),
591 responder: responder.clone(),
592 })) {
593 warn!("handle_request: error while trying to schedule `{}`: {:?}", alarm_id, e);
594 responder
595 .borrow_mut()
596 .take()
597 .expect("always present if call fails")
598 .send(Err(fta::WakeAlarmsError::Internal))
599 .unwrap();
600 }
601 }
602 fta::WakeAlarmsRequest::Cancel { alarm_id, .. } => {
603 handle_cancel(alarm_id, conn_id, &mut cmd).await;
606 }
607 fta::WakeAlarmsRequest::Set { notifier, deadline, mode, alarm_id, responder } => {
608 debug!(
610 "handle_request: scheduling alarm_id: \"{alarm_id}\"\n\tconn_id: {conn_id:?}\n\tdeadline: {}",
611 format_timer(deadline.into())
612 );
613 if let Err(e) = log_long_op!(cmd.send(Cmd::Start {
615 conn_id,
616 deadline: timers::Deadline::Boot(deadline.into()),
617 mode: Some(mode),
618 alarm_id: alarm_id.clone(),
619 responder: Rc::new(RefCell::new(Some(notifier))),
620 })) {
621 warn!("handle_request: error while trying to schedule `{}`: {:?}", alarm_id, e);
622 responder.send(Err(fta::WakeAlarmsError::Internal)).unwrap();
623 } else {
624 responder.send(Ok(())).unwrap();
626 }
627 }
628 fta::WakeAlarmsRequest::_UnknownMethod { .. } => {}
629 };
630}
631
632pub struct Loop {
639 snd: mpsc::Sender<Cmd>,
642}
643
644impl Loop {
645 pub fn new(
660 scope: fasync::ScopeHandle,
661 device_proxy: ffhh::DeviceProxy,
662 inspect: finspect::Node,
663 utc_clock: fxr::UtcClock,
664 ) -> Self {
665 let hw_device_timer_ops = HardwareTimerOps::new(device_proxy);
666 Loop::new_internal(scope, hw_device_timer_ops, inspect, utc_clock)
667 }
668
669 pub fn new_emulated(
683 scope: fasync::ScopeHandle,
684 inspect: finspect::Node,
685 utc_clock: fxr::UtcClock,
686 ) -> Self {
687 let timer_ops = Box::new(EmulationTimerOps::new());
688 Loop::new_internal(scope, timer_ops, inspect, utc_clock)
689 }
690
691 fn new_internal(
692 scope: fasync::ScopeHandle,
693 timer_ops: Box<dyn TimerOps>,
694 inspect: finspect::Node,
695 utc_clock: fxr::UtcClock,
696 ) -> Self {
697 let utc_transform = Rc::new(RefCell::new(
698 utc_clock.get_details().expect("has UTC clock READ capability").reference_to_synthetic,
699 ));
700
701 let (snd, rcv) = mpsc::channel(CHANNEL_SIZE);
702 let loop_scope = scope.clone();
703
704 scope.spawn_local(wake_timer_loop(
705 loop_scope,
706 snd.clone(),
707 rcv,
708 timer_ops,
709 inspect,
710 utc_transform,
711 ));
712 scope.spawn_local(monitor_utc_clock_changes(utc_clock, snd.clone()));
713 Self { snd }
714 }
715
716 fn get_sender(&self) -> mpsc::Sender<Cmd> {
719 self.snd.clone()
720 }
721}
722
723async fn monitor_utc_clock_changes(utc_clock: fxr::UtcClock, mut cmd: mpsc::Sender<Cmd>) {
726 let koid = utc_clock.as_handle_ref().koid();
727 log::info!("monitor_utc_clock_changes: entry");
728 loop {
729 fasync::OnSignals::new(utc_clock.as_handle_ref(), zx::Signals::CLOCK_UPDATED)
731 .await
732 .expect("UTC clock is readable");
733
734 let transform =
735 utc_clock.get_details().expect("UTC clock details are readable").reference_to_synthetic;
736 log::debug!("Received a UTC update: koid={koid:?}: {transform:?}");
737 if let Err(err) = cmd.send(Cmd::UtcUpdated { transform }).await {
738 log::warn!("monitor_utc_clock_changes: exit: {err:?}");
740 break;
741 }
742 }
743}
744
745async fn wait_signaled<H: fidl::AsHandleRef>(handle: &H) {
758 fasync::OnSignals::new(&handle.as_handle_ref(), zx::Signals::EVENT_SIGNALED)
759 .await
760 .expect("infallible");
761}
762
763pub(crate) fn signal(event: &zx::Event) {
764 event.signal(zx::Signals::NONE, zx::Signals::EVENT_SIGNALED).expect("infallible");
765}
766
767#[derive(Debug, Clone, Copy)]
775struct TimerDuration {
776 resolution: zx::BootDuration,
778 ticks: u64,
781}
782
783impl Eq for TimerDuration {}
786
787impl std::cmp::PartialOrd for TimerDuration {
788 fn partial_cmp(&self, other: &TimerDuration) -> Option<std::cmp::Ordering> {
789 Some(self.cmp(other))
790 }
791}
792
793impl std::cmp::PartialEq for TimerDuration {
794 fn eq(&self, other: &Self) -> bool {
795 self.cmp(other) == std::cmp::Ordering::Equal
796 }
797}
798
799impl std::cmp::Ord for TimerDuration {
800 fn cmp(&self, other: &TimerDuration) -> std::cmp::Ordering {
803 let self_ticks_128: i128 = self.ticks as i128;
804 let self_resolution: i128 = self.resolution_as_nanos() as i128;
805 let self_nanos = self_resolution * self_ticks_128;
806
807 let other_ticks_128: i128 = other.ticks as i128;
808 let other_resolution: i128 = other.resolution_as_nanos() as i128;
809 let other_nanos = other_resolution * other_ticks_128;
810
811 self_nanos.cmp(&other_nanos)
812 }
813}
814
815impl std::fmt::Display for TimerDuration {
816 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
820 let ticks = self.ticks;
821 let resolution = self.resolution();
822 write!(f, "{}x{}", ticks, format_duration(resolution),)
824 }
825}
826
827impl TimerDuration {
828 fn max() -> Self {
830 TimerDuration::new(zx::BootDuration::from_nanos(1), *I64_MAX_AS_U64)
831 }
832
833 fn zero() -> Self {
835 TimerDuration::new(zx::BootDuration::from_nanos(1), 0)
836 }
837
838 fn new(resolution: zx::BootDuration, ticks: u64) -> Self {
840 Self { resolution, ticks }
841 }
842
843 fn new_with_resolution(res_source: &TimerDuration, ticks: u64) -> Self {
846 Self::new(res_source.resolution, ticks)
847 }
848
849 fn duration(&self) -> zx::BootDuration {
854 let duration_as_nanos = self.resolution_as_nanos() * self.ticks;
855 let clamp_duration = std::cmp::min(*I32_MAX_AS_U64, duration_as_nanos);
856 zx::BootDuration::from_nanos(clamp_duration.try_into().expect("result was clamped"))
857 }
858
859 fn resolution(&self) -> zx::BootDuration {
861 self.resolution
862 }
863
864 fn resolution_as_nanos(&self) -> u64 {
865 self.resolution().into_nanos().try_into().expect("resolution is never negative")
866 }
867
868 fn ticks(&self) -> u64 {
870 self.ticks
871 }
872}
873
874impl From<zx::BootDuration> for TimerDuration {
875 fn from(d: zx::BootDuration) -> TimerDuration {
876 let nanos = d.into_nanos();
877 assert!(nanos >= 0);
878 let nanos_u64 = nanos.try_into().expect("guarded by assert");
879 TimerDuration::new(zx::BootDuration::from_nanos(1), nanos_u64)
880 }
881}
882
883impl std::ops::Div for TimerDuration {
884 type Output = u64;
885 fn div(self, rhs: Self) -> Self::Output {
886 let self_nanos = self.resolution_as_nanos() * self.ticks;
887 let rhs_nanos = rhs.resolution_as_nanos() * rhs.ticks;
888 self_nanos / rhs_nanos
889 }
890}
891
892impl std::ops::Mul<u64> for TimerDuration {
893 type Output = Self;
894 fn mul(self, rhs: u64) -> Self::Output {
895 Self::new(self.resolution, self.ticks * rhs)
896 }
897}
898
899#[derive(Debug)]
901pub(crate) struct TimerConfig {
902 resolutions: Vec<zx::BootDuration>,
910 max_ticks: u64,
915 id: u64,
917}
918
919impl TimerConfig {
920 fn new_from_data(timer_id: u64, resolutions: &[zx::BootDuration], max_ticks: u64) -> Self {
923 debug!(
924 "TimerConfig: resolutions: {:?}, max_ticks: {}, timer_id: {}",
925 resolutions.iter().map(|r| format_duration(*r)).collect::<Vec<_>>(),
926 max_ticks,
927 timer_id
928 );
929 let resolutions = resolutions.iter().map(|d| *d).collect::<Vec<zx::BootDuration>>();
930 TimerConfig { resolutions, max_ticks, id: timer_id }
931 }
932
933 fn new_empty() -> Self {
934 error!("TimerConfig::new_empty() called, this is not OK.");
935 TimerConfig { resolutions: vec![], max_ticks: 0, id: 0 }
936 }
937
938 fn pick_setting(&self, duration: zx::BootDuration) -> TimerDuration {
948 assert!(self.resolutions.len() > 0, "there must be at least one supported resolution");
949
950 if duration <= zx::BootDuration::ZERO {
953 return TimerDuration::new(self.resolutions[0], 1);
954 }
955
956 let mut best_positive_slack = TimerDuration::zero();
963 let mut best_negative_slack = TimerDuration::max();
964
965 if self.max_ticks == 0 {
966 return TimerDuration::new(zx::BootDuration::from_millis(1), 0);
967 }
968 let duration_slack: TimerDuration = duration.into();
969
970 for res1 in self.resolutions.iter() {
971 let smallest_unit = TimerDuration::new(*res1, 1);
972 let max_tick_at_res = TimerDuration::new(*res1, self.max_ticks);
973
974 let smallest_slack_larger_than_duration = smallest_unit > duration_slack;
975 let largest_slack_smaller_than_duration = max_tick_at_res < duration_slack;
976
977 if smallest_slack_larger_than_duration {
978 if duration_slack == TimerDuration::zero() {
979 best_negative_slack = TimerDuration::zero();
980 } else if smallest_unit < best_negative_slack {
981 best_negative_slack = smallest_unit;
982 }
983 }
984 if largest_slack_smaller_than_duration {
985 if max_tick_at_res > best_positive_slack
986 || best_positive_slack == TimerDuration::zero()
987 {
988 best_positive_slack = max_tick_at_res;
989 }
990 }
991
992 if !smallest_slack_larger_than_duration && !largest_slack_smaller_than_duration {
994 let q = duration_slack / smallest_unit;
997 let d = smallest_unit * q;
998 if d == duration_slack {
999 return d;
1001 } else {
1002 if d > best_positive_slack {
1004 best_positive_slack = TimerDuration::new_with_resolution(&smallest_unit, q);
1005 }
1006 let d_plus = TimerDuration::new_with_resolution(&smallest_unit, q + 1);
1007 if d_plus < best_negative_slack {
1008 best_negative_slack = d_plus;
1009 }
1010 }
1011 }
1012 }
1013
1014 let p_slack = duration - best_positive_slack.duration();
1015 let n_slack = best_negative_slack.duration() - duration;
1016
1017 let ret = if p_slack < n_slack && best_positive_slack.duration().into_nanos() > 0 {
1022 best_positive_slack
1023 } else {
1024 best_negative_slack
1025 };
1026 debug!("TimerConfig: picked slack: {} for duration: {}", ret, format_duration(duration));
1027 assert!(
1028 ret.duration().into_nanos() >= 0,
1029 "ret: {}, p_slack: {}, n_slack: {}, orig.duration: {}\n\tbest_p_slack: {}\n\tbest_n_slack: {}\n\ttarget: {}\n\t 1: {} 2: {:?}, 3: {:?}",
1030 ret,
1031 format_duration(p_slack),
1032 format_duration(n_slack),
1033 format_duration(duration),
1034 best_positive_slack,
1035 best_negative_slack,
1036 duration_slack,
1037 p_slack != zx::BootDuration::ZERO,
1038 p_slack,
1039 zx::BootDuration::ZERO,
1040 );
1041 ret
1042 }
1043}
1044
1045async fn get_timer_properties(hrtimer: &Box<dyn TimerOps>) -> TimerConfig {
1046 debug!("get_timer_properties: requesting timer properties.");
1047 hrtimer.get_timer_properties().await
1048}
1049
1050struct TimerState {
1052 task: fasync::Task<()>,
1054 deadline: fasync::BootInstant,
1056}
1057
1058async fn wake_timer_loop(
1067 scope: fasync::ScopeHandle,
1068 snd: mpsc::Sender<Cmd>,
1069 mut cmds: mpsc::Receiver<Cmd>,
1070 timer_proxy: Box<dyn TimerOps>,
1071 inspect: finspect::Node,
1072 utc_transform: Rc<RefCell<fxr::UtcClockTransform>>,
1073) {
1074 debug!("wake_timer_loop: started");
1075
1076 let mut timers = timers::Heap::new(utc_transform.clone());
1077 let timer_config = get_timer_properties(&timer_proxy).await;
1078
1079 #[allow(clippy::collection_is_never_read)]
1082 let mut hrtimer_status: Option<TimerState> = None;
1083
1084 let now_prop = inspect.create_int("now_ns", 0);
1091 let now_formatted_prop = inspect.create_string("now_formatted", "");
1092 let pending_timers_count_prop = inspect.create_uint("pending_timers_count", 0);
1093 let pending_timers_prop = inspect.create_string("pending_timers", "");
1094 let _deadline_histogram_prop = inspect.create_int_exponential_histogram(
1095 "requested_deadlines_ns",
1096 finspect::ExponentialHistogramParams {
1097 floor: 0,
1098 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1099 step_multiplier: 10,
1101 buckets: 16,
1102 },
1103 );
1104 let slack_histogram_prop = inspect.create_int_exponential_histogram(
1105 "slack_ns",
1106 finspect::ExponentialHistogramParams {
1107 floor: 0,
1108 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1109 step_multiplier: 10,
1110 buckets: 16,
1111 },
1112 );
1113 let schedule_delay_prop = inspect.create_int_exponential_histogram(
1114 "schedule_delay_ns",
1115 finspect::ExponentialHistogramParams {
1116 floor: 0,
1117 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1118 step_multiplier: 10,
1119 buckets: 16,
1120 },
1121 );
1122 let boot_deadlines_count_prop = inspect.create_uint("boot_deadlines_count", 0);
1123 let utc_deadlines_count_prop = inspect.create_uint("utc_deadlines_count", 0);
1124 let hw_node = inspect.create_child("hardware");
1126 let current_hw_deadline_prop = hw_node.create_string("current_deadline", "");
1127 let remaining_until_alarm_prop = hw_node.create_string("remaining_until_alarm", "");
1128
1129 let debug_node = inspect.create_child("debug_node");
1131 let start_notify_setup_count = debug_node.create_int("start_notify_setup", 0);
1132 let start_count = debug_node.create_int("start_count", 0);
1133 let responder_count = debug_node.create_int("responder_count", 0);
1134 let stop_count = debug_node.create_int("stop", 0);
1135 let stop_responder_count = debug_node.create_int("stop_responder", 0);
1136 let stop_hrtimer_count = debug_node.create_int("stop_hrtimer", 0);
1137 let schedule_hrtimer_count = debug_node.create_int("schedule_hrtimer", 0);
1138 let alarm_count = debug_node.create_int("alarm", 0);
1139 let alarm_fidl_count = debug_node.create_int("alarm_fidl", 0);
1140 let alarm_driver_count = debug_node.create_int("alarm_driver", 0);
1141 let utc_update_count = debug_node.create_int("utc_update", 0);
1142 let status_count = debug_node.create_int("status", 0);
1143 let loop_count = debug_node.create_int("loop_count", 0);
1144
1145 let hrtimer_node = debug_node.create_child("hrtimer");
1146
1147 const LRU_CACHE_CAPACITY: NonZeroUsize = NonZeroUsize::new(100).unwrap();
1148 let mut error_cache = lru::LruCache::new(LRU_CACHE_CAPACITY);
1149
1150 while let Some(cmd) = cmds.next().await {
1151 let _i = ScopedInc::new(&loop_count);
1152 trace::duration!("alarms", "Cmd");
1153 let now = fasync::BootInstant::now();
1155 now_prop.set(now.into_nanos());
1156 trace::instant!("alarms", "wake_timer_loop", trace::Scope::Process, "now" => now.into_nanos());
1157 match cmd {
1158 Cmd::Start { conn_id, deadline, mode, alarm_id, responder } => {
1159 let _i = ScopedInc::new(&start_count);
1160 trace::duration!("alarms", "Cmd::Start");
1161 fuchsia_trace::flow_step!(
1162 "alarms",
1163 "hrtimer_lifecycle",
1164 timers::get_trace_id(&alarm_id)
1165 );
1166 debug!(
1168 "wake_timer_loop: START alarm_id: \"{}\", conn_id: {:?}\n\tdeadline: {}\n\tnow: {}",
1169 alarm_id,
1170 conn_id,
1171 deadline,
1172 format_timer(now.into()),
1173 );
1174
1175 defer! {
1176 let _i = ScopedInc::new(&start_notify_setup_count);
1177 if let Some(mode) = mode {
1179 if let fta::SetMode::NotifySetupDone(setup_done) = mode {
1180 signal(&setup_done);
1182 debug!("wake_timer_loop: START: setup_done signaled");
1183 };
1184 }
1185 }
1186 let deadline_boot = deadline.as_boot(&*utc_transform.borrow());
1187
1188 match deadline {
1192 timers::Deadline::Boot(_) => boot_deadlines_count_prop.add(1),
1193 timers::Deadline::Utc(_) => utc_deadlines_count_prop.add(1),
1194 };
1195
1196 if timers::Heap::expired(now, deadline_boot) {
1197 trace::duration!("alarms", "Cmd::Start:immediate");
1198 fuchsia_trace::flow_step!(
1199 "alarms",
1200 "hrtimer_lifecycle",
1201 timers::get_trace_id(&alarm_id)
1202 );
1203 let (_lease, keep_alive) = zx::EventPair::create();
1205 debug!(
1206 "[{}] wake_timer_loop: bogus lease {:?}",
1207 line!(),
1208 keep_alive.koid().unwrap()
1209 );
1210
1211 {
1212 let _i1 = ScopedInc::new(&responder_count);
1213 if let Err(e) = responder
1214 .send(&alarm_id, Ok(keep_alive))
1215 .expect("responder is always present")
1216 {
1217 error!(
1218 "wake_timer_loop: conn_id: {conn_id:?}, alarm: {alarm_id}: could not notify, dropping: {e}",
1219 );
1220 } else {
1221 debug!(
1222 "wake_timer_loop: conn_id: {conn_id:?}, alarm: {alarm_id}: EXPIRED IMMEDIATELY\n\tdeadline({}) <= now({})\n\tfull deadline: {}",
1223 format_timer(deadline_boot.into()),
1224 format_timer(now.into()),
1225 deadline,
1226 )
1227 }
1228 }
1229 } else {
1230 trace::duration!("alarms", "Cmd::Start:regular");
1231 fuchsia_trace::flow_step!(
1232 "alarms",
1233 "hrtimer_lifecycle",
1234 timers::get_trace_id(&alarm_id)
1235 );
1236 let was_empty = timers.is_empty();
1238
1239 let deadline_before = timers.peek_deadline_as_boot();
1240 let node = match deadline {
1241 timers::Deadline::Boot(_) => {
1242 timers.new_node_boot(deadline_boot, alarm_id, conn_id, responder)
1243 }
1244 timers::Deadline::Utc(d) => {
1245 timers.new_node_utc(d, alarm_id, conn_id, responder)
1246 }
1247 };
1248 timers.push(node);
1249 let deadline_after = timers.peek_deadline_as_boot();
1250
1251 let deadline_changed = is_deadline_changed(deadline_before, deadline_after);
1252 let needs_cancel = !was_empty && deadline_changed;
1253 let needs_reschedule = was_empty || deadline_changed;
1254
1255 if needs_reschedule {
1256 let schedulable_deadline = deadline_after.unwrap_or(deadline_boot);
1258 if needs_cancel {
1259 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1260 }
1261 hrtimer_status = Some(
1262 schedule_hrtimer(
1263 scope.clone(),
1264 now,
1265 &timer_proxy,
1266 schedulable_deadline,
1267 snd.clone(),
1268 &timer_config,
1269 &schedule_delay_prop,
1270 &hrtimer_node,
1271 )
1272 .await,
1273 );
1274 }
1275 }
1276 }
1277 Cmd::StopById { timer_id, done } => {
1278 let _i = ScopedInc::new(&stop_count);
1279 defer! {
1280 signal(&done);
1281 }
1282 trace::duration!("alarms", "Cmd::StopById", "alarm_id" => timer_id.alarm());
1283 fuchsia_trace::flow_step!(
1284 "alarms",
1285 "hrtimer_lifecycle",
1286 timers::get_trace_id(&timer_id.alarm())
1287 );
1288 debug!("wake_timer_loop: STOP timer: {}", timer_id);
1289 let deadline_before = timers.peek_deadline_as_boot();
1290
1291 if let Some(timer_node) = timers.remove_by_id(&timer_id) {
1292 let deadline_after = timers.peek_deadline_as_boot();
1293
1294 {
1295 let _i = ScopedInc::new(&stop_responder_count);
1296 if let Some(res) = timer_node
1297 .get_responder()
1298 .send(timer_node.id().alarm(), Err(fta::WakeAlarmsError::Dropped))
1299 {
1300 res.expect("infallible");
1302 }
1303 }
1304 if is_deadline_changed(deadline_before, deadline_after) {
1305 let _i = ScopedInc::new(&stop_hrtimer_count);
1306 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1307 }
1308 if let Some(deadline) = deadline_after {
1309 let _i = ScopedInc::new(&schedule_hrtimer_count);
1310 let new_timer_state = schedule_hrtimer(
1313 scope.clone(),
1314 now,
1315 &timer_proxy,
1316 deadline,
1317 snd.clone(),
1318 &timer_config,
1319 &schedule_delay_prop,
1320 &hrtimer_node,
1321 )
1322 .await;
1323 let old_hrtimer_status = hrtimer_status.replace(new_timer_state);
1324 if let Some(task) = old_hrtimer_status.map(|ev| ev.task) {
1325 log_long_op!(task);
1329 }
1330 } else {
1331 hrtimer_status = None;
1333 }
1334 } else {
1335 debug!("wake_timer_loop: STOP: removed non-imminent timer: {}", timer_id);
1337 }
1338 }
1339 Cmd::Alarm { expired_deadline, keep_alive } => {
1340 let _i = ScopedInc::new(&alarm_count);
1341
1342 trace::duration!("alarms", "Cmd::Alarm");
1343 debug!(
1348 "wake_timer_loop: ALARM!!! reached deadline: {}, wakey-wakey! {:?}",
1349 format_timer(expired_deadline.into()),
1350 keep_alive.koid().unwrap(),
1351 );
1352 let expired_count =
1353 notify_all(&mut timers, &keep_alive, now, None, &slack_histogram_prop)
1354 .expect("notification succeeds");
1355 if expired_count == 0 {
1356 debug!("wake_timer_loop: no expired alarms, reset hrtimer state");
1359 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1360 }
1361 hrtimer_status = match timers.peek_deadline_as_boot() {
1363 None => None,
1364 Some(deadline) => Some(
1365 schedule_hrtimer(
1366 scope.clone(),
1367 now,
1368 &timer_proxy,
1369 deadline,
1370 snd.clone(),
1371 &timer_config,
1372 &schedule_delay_prop,
1373 &hrtimer_node,
1374 )
1375 .await,
1376 ),
1377 }
1378 }
1379 Cmd::AlarmFidlError { expired_deadline, error } => {
1380 let _i = ScopedInc::new(&alarm_fidl_count);
1381
1382 trace::duration!("alarms", "Cmd::AlarmFidlError");
1383 let error_string = format!("{}", error);
1387 if !error_cache.contains(&error_string) {
1388 warn!(
1389 "wake_timer_loop: FIDL error: {}, deadline: {}, now: {}",
1390 error,
1391 format_timer(expired_deadline.into()),
1392 format_timer(now.into()),
1393 );
1394 error_cache.put(error_string, ());
1395 }
1396 let (_dummy_lease, peer) = zx::EventPair::create();
1399 debug!(
1400 "bogus lease: {:?} fidl error [{}:{}]",
1401 peer.koid().unwrap(),
1402 file!(),
1403 line!()
1404 );
1405 notify_all(
1406 &mut timers,
1407 &peer,
1408 now,
1409 Some(TimerOpsError::Fidl(error)),
1410 &slack_histogram_prop,
1411 )
1412 .expect("notification succeeds");
1413 hrtimer_status = match timers.peek_deadline_as_boot() {
1414 None => None, Some(deadline) => Some(
1416 schedule_hrtimer(
1417 scope.clone(),
1418 now,
1419 &timer_proxy,
1420 deadline,
1421 snd.clone(),
1422 &timer_config,
1423 &schedule_delay_prop,
1424 &hrtimer_node,
1425 )
1426 .await,
1427 ),
1428 }
1429 }
1430 Cmd::AlarmDriverError {
1431 expired_deadline,
1432 error,
1433 timer_config_id,
1434 resolution_nanos,
1435 ticks,
1436 } => {
1437 let _i = ScopedInc::new(&alarm_driver_count);
1438
1439 trace::duration!("alarms", "Cmd::AlarmDriverError");
1440 let (_dummy_lease, peer) = zx::EventPair::create();
1441 debug!(
1442 "bogus lease: {:?} driver error. [{}:{}]",
1443 peer.koid().unwrap(),
1444 file!(),
1445 line!()
1446 );
1447 notify_all(
1448 &mut timers,
1449 &peer,
1450 now,
1451 Some(TimerOpsError::Driver(error)),
1452 &slack_histogram_prop,
1453 )
1454 .expect("notification succeeds");
1455 match error {
1456 fidl_fuchsia_hardware_hrtimer::DriverError::Canceled => {
1457 debug!(
1459 "wake_timer_loop: CANCELED timer at deadline: {}",
1460 format_timer(expired_deadline.into())
1461 );
1462 }
1463 _ => {
1464 error!(
1465 "wake_timer_loop: DRIVER SAYS: {:?}, deadline: {}, now: {}\n\ttimer_id={}\n\tresolution={}\n\tticks={}",
1466 error,
1467 format_timer(expired_deadline.into()),
1468 format_timer(now.into()),
1469 timer_config_id,
1470 resolution_nanos,
1471 ticks,
1472 );
1473 hrtimer_status = match timers.peek_deadline_as_boot() {
1477 None => None,
1478 Some(deadline) => Some(
1479 schedule_hrtimer(
1480 scope.clone(),
1481 now,
1482 &timer_proxy,
1483 deadline,
1484 snd.clone(),
1485 &timer_config,
1486 &schedule_delay_prop,
1487 &hrtimer_node,
1488 )
1489 .await,
1490 ),
1491 }
1492 }
1493 }
1494 }
1495 Cmd::UtcUpdated { transform } => {
1496 let _i = ScopedInc::new(&utc_update_count);
1497
1498 trace::duration!("alarms", "Cmd::UtcUpdated");
1499 debug!("wake_timer_loop: applying new clock transform: {transform:?}");
1500
1501 *utc_transform.borrow_mut() = transform;
1504
1505 if hrtimer_status.is_some() {
1508 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1509 hrtimer_status = match timers.peek_deadline_as_boot() {
1511 None => None,
1512 Some(deadline) => Some(
1513 schedule_hrtimer(
1514 scope.clone(),
1515 now,
1516 &timer_proxy,
1517 deadline,
1518 snd.clone(),
1519 &timer_config,
1520 &schedule_delay_prop,
1521 &hrtimer_node,
1522 )
1523 .await,
1524 ),
1525 }
1526 }
1527 }
1528 }
1529
1530 {
1531 let _i = ScopedInc::new(&status_count);
1532
1533 trace::duration!("timekeeper", "inspect");
1538 let now_formatted = format_timer(now.into());
1539 debug!("wake_timer_loop: now: {}", now_formatted);
1540 now_formatted_prop.set(&now_formatted);
1541
1542 let pending_timers_count: u64 =
1543 timers.timer_count().try_into().expect("always convertible");
1544 debug!("wake_timer_loop: currently pending timer count: {}", pending_timers_count);
1545 pending_timers_count_prop.set(pending_timers_count);
1546
1547 let pending_timers = format!("{}", timers);
1548 debug!("wake_timer_loop: currently pending timers: \n\t{}", timers);
1549 pending_timers_prop.set(&pending_timers);
1550
1551 let current_deadline: String = hrtimer_status
1552 .as_ref()
1553 .map(|s| format!("{}", format_timer(s.deadline.into())))
1554 .unwrap_or_else(|| "(none)".into());
1555 debug!("wake_timer_loop: current hardware timer deadline: {:?}", current_deadline);
1556 current_hw_deadline_prop.set(¤t_deadline);
1557
1558 let remaining_duration_until_alarm = hrtimer_status
1559 .as_ref()
1560 .map(|s| format!("{}", format_duration((s.deadline - now).into())))
1561 .unwrap_or_else(|| "(none)".into());
1562 debug!(
1563 "wake_timer_loop: remaining duration until alarm: {}",
1564 remaining_duration_until_alarm
1565 );
1566 remaining_until_alarm_prop.set(&remaining_duration_until_alarm);
1567 debug!("---");
1568 }
1569 }
1570
1571 log::info!("wake_timer_loop: exiting. This is only correct in test code.");
1574}
1575
1576async fn schedule_hrtimer(
1590 scope: fasync::ScopeHandle,
1591 now: fasync::BootInstant,
1592 hrtimer: &Box<dyn TimerOps>,
1593 deadline: fasync::BootInstant,
1594 mut command_send: mpsc::Sender<Cmd>,
1595 timer_config: &TimerConfig,
1596 _schedule_delay_histogram: &finspect::IntExponentialHistogramProperty,
1597 debug_node: &finspect::Node,
1598) -> TimerState {
1599 let timeout = std::cmp::max(zx::BootDuration::ZERO, deadline - now);
1600 trace::duration!("alarms", "schedule_hrtimer", "timeout" => timeout.into_nanos());
1601 let hrtimer_scheduled = zx::Event::create();
1603
1604 let schedule_count = debug_node.create_int("schedule", 0);
1605 let hrtimer_wait_count = debug_node.create_int("hrtimer_wait", 0);
1606 let wait_signaled_count = debug_node.create_int("wait_signaled", 0);
1607
1608 let _sc = ScopedInc::new(&schedule_count);
1609
1610 debug!(
1611 "schedule_hrtimer:\n\tnow: {}\n\tdeadline: {}\n\ttimeout: {}",
1612 format_timer(now.into()),
1613 format_timer(deadline.into()),
1614 format_duration(timeout),
1615 );
1616
1617 let slack = timer_config.pick_setting(timeout);
1618 let resolution_nanos = slack.resolution.into_nanos();
1619 let useful_ticks = std::cmp::max(MIN_USEFUL_TICKS, slack.ticks());
1622
1623 trace::instant!("alarms", "hrtimer:programmed",
1624 trace::Scope::Process,
1625 "resolution_ns" => resolution_nanos,
1626 "ticks" => useful_ticks
1627 );
1628 let timer_config_id = timer_config.id;
1629 let start_and_wait_fut = {
1630 let _sc = ScopedInc::new(&hrtimer_wait_count);
1631 hrtimer.start_and_wait(
1632 timer_config.id,
1633 &ffhh::Resolution::Duration(resolution_nanos),
1634 useful_ticks,
1635 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible"),
1636 )
1637 };
1638
1639 let hrtimer_scheduled_if_error =
1640 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1641 let hrtimer_task = scope.spawn_local(async move {
1642 debug!("hrtimer_task: waiting for hrtimer driver response");
1643 trace::instant!("alarms", "hrtimer:started", trace::Scope::Process);
1644 let response = start_and_wait_fut.await;
1645 trace::instant!("alarms", "hrtimer:response", trace::Scope::Process);
1646 match response {
1647 Err(TimerOpsError::Fidl(e)) => {
1648 defer! {
1649 signal(&hrtimer_scheduled_if_error);
1651 }
1652 trace::instant!("alarms", "hrtimer:response:fidl_error", trace::Scope::Process);
1653 command_send
1654 .start_send(Cmd::AlarmFidlError { expired_deadline: now, error: e })
1655 .unwrap();
1656 }
1658 Err(TimerOpsError::Driver(e)) => {
1659 defer! {
1660 signal(&hrtimer_scheduled_if_error);
1663 }
1664 let driver_error_str = format!("{:?}", e);
1665 trace::instant!("alarms", "hrtimer:response:driver_error", trace::Scope::Process, "error" => &driver_error_str[..]);
1666 debug!("schedule_hrtimer: hrtimer driver error: {:?}", e);
1669 command_send
1670 .start_send(Cmd::AlarmDriverError {
1671 expired_deadline: now,
1672 error: e,
1673 timer_config_id,
1674 resolution_nanos,
1675 ticks: useful_ticks,
1676 })
1677 .unwrap();
1678 }
1680 Ok(keep_alive) => {
1681 trace::instant!("alarms", "hrtimer:response:alarm", trace::Scope::Process);
1682 debug!("hrtimer: got alarm response: {:?}", keep_alive);
1683 command_send
1685 .start_send(Cmd::Alarm { expired_deadline: deadline, keep_alive })
1686 .unwrap();
1687 }
1688 }
1689 debug!("hrtimer_task: exiting task.");
1690 trace::instant!("alarms", "hrtimer:task_exit", trace::Scope::Process);
1691 }).into();
1692 debug!("schedule_hrtimer: waiting for event to be signaled");
1693
1694 {
1695 let _i = ScopedInc::new(&wait_signaled_count);
1696 log_long_op!(wait_signaled(&hrtimer_scheduled));
1698 }
1699
1700 let now_after_signaled = fasync::BootInstant::now();
1701 let duration_until_scheduled: zx::BootDuration = (now_after_signaled - now).into();
1702 if duration_until_scheduled > zx::BootDuration::from_nanos(LONG_DELAY_NANOS) {
1703 trace::duration!("alarms", "schedule_hrtimer:unusual_duration",
1704 "duration" => duration_until_scheduled.into_nanos());
1705 warn!(
1706 "unusual duration until hrtimer scheduled: {}",
1707 format_duration(duration_until_scheduled)
1708 );
1709 }
1710 debug!("schedule_hrtimer: hrtimer wake alarm has been scheduled.");
1713 TimerState { task: hrtimer_task, deadline }
1714}
1715
1716fn notify_all(
1727 timers: &mut timers::Heap,
1728 lease_prototype: &zx::EventPair,
1729 reference_instant: fasync::BootInstant,
1730 timer_ops_error: Option<TimerOpsError>,
1731 _unusual_slack_histogram: &finspect::IntExponentialHistogramProperty,
1732) -> Result<usize> {
1733 trace::duration!("alarms", "notify_all");
1734 let now = fasync::BootInstant::now();
1735 let mut expired = 0;
1736 while let Some(timer_node) = timers.maybe_expire_earliest(reference_instant) {
1737 expired += 1;
1738 let deadline = timer_node.get_boot_deadline();
1740 let alarm = timer_node.id().alarm();
1741 let alarm_id = alarm.to_string();
1742 trace::duration!("alarms", "notify_all:notified", "alarm_id" => &*alarm_id);
1743 fuchsia_trace::flow_step!("alarms", "hrtimer_lifecycle", timers::get_trace_id(&alarm_id));
1744 let conn_id = timer_node.id().conn.clone();
1745 let slack: zx::BootDuration = deadline - now;
1746 if slack < zx::BootDuration::from_nanos(-LONG_DELAY_NANOS) {
1747 trace::duration!("alarms", "schedule_hrtimer:unusual_slack", "slack" => slack.into_nanos());
1748 warn!(
1750 "alarm id: {} had an unusually large slack: {}",
1751 alarm_id,
1752 format_duration(slack)
1753 );
1754 }
1755 if slack < zx::BootDuration::ZERO {
1756 }
1759 if let Some(ref err) = timer_ops_error {
1760 if !err.is_canceled() {
1763 timer_node.get_responder().send(alarm, Err(err.clone().into()));
1764 continue;
1765 }
1766 }
1767 debug!(
1768 concat!(
1769 "wake_alarm_loop: ALARM alarm_id: \"{}\"\n\tdeadline: {},\n\tconn_id: {:?},\n\t",
1770 "reference_instant: {},\n\tnow: {},\n\tslack: {}",
1771 ),
1772 alarm_id,
1773 format_timer(deadline.into()),
1774 conn_id,
1775 format_timer(reference_instant.into()),
1776 format_timer(now.into()),
1777 format_duration(slack),
1778 );
1779 let lease = lease_prototype.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1780 trace::instant!("alarms", "notify", trace::Scope::Process, "alarm_id" => &alarm_id[..], "conn_id" => conn_id);
1781 if let Some(Err(e)) = timer_node.get_responder().send(alarm, Ok(lease)) {
1782 error!("could not signal responder: {:?}", e);
1783 }
1784 trace::instant!("alarms", "notified", trace::Scope::Process);
1785 }
1786 trace::instant!("alarms", "notify", trace::Scope::Process, "expired_count" => expired);
1787 debug!("notify_all: expired count: {}", expired);
1788 Ok(expired)
1789 }
1791
1792pub async fn connect_to_hrtimer_async() -> Result<ffhh::DeviceProxy> {
1801 debug!("connect_to_hrtimer: trying service");
1802 let service = Service::open(ffhh::ServiceMarker).context("failed to open hrtimer service")?;
1803 let instance = service.watch_for_any().await.context("no hrtimer devices found")?;
1804 instance.connect_to_device().context("failed to connect to hrtimer device")
1805}
1806
1807#[cfg(test)]
1808mod tests {
1809 use super::*;
1810 use assert_matches::assert_matches;
1811 use diagnostics_assertions::{AnyProperty, assert_data_tree};
1812 use fuchsia_async::TestExecutor;
1813 use futures::select;
1814 use std::pin::pin;
1815 use test_case::test_case;
1816 use test_util::{assert_gt, assert_lt};
1817
1818 fn fake_wake_lease() -> fidl_fuchsia_power_system::LeaseToken {
1819 let (_lease, peer) = zx::EventPair::create();
1820 peer
1821 }
1822
1823 #[test]
1824 fn timer_duration_no_overflow() {
1825 let duration1 = TimerDuration {
1826 resolution: zx::BootDuration::from_seconds(100_000_000),
1827 ticks: u64::MAX,
1828 };
1829 let duration2 = TimerDuration {
1830 resolution: zx::BootDuration::from_seconds(110_000_000),
1831 ticks: u64::MAX,
1832 };
1833 assert_eq!(duration1, duration1);
1834 assert_eq!(duration2, duration2);
1835
1836 assert_lt!(duration1, duration2);
1837 assert_gt!(duration2, duration1);
1838 }
1839
1840 #[test_case(
1841 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1842 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1843 )]
1844 #[test_case(
1845 TimerDuration::new(zx::BootDuration::from_nanos(1), 10),
1846 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1847 )]
1848 #[test_case(
1849 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1850 TimerDuration::new(zx::BootDuration::from_nanos(1), 10)
1851 )]
1852 #[test_case(
1853 TimerDuration::new(zx::BootDuration::from_micros(1), 1),
1854 TimerDuration::new(zx::BootDuration::from_nanos(1), 1000)
1855 )]
1856 fn test_slack_eq(one: TimerDuration, other: TimerDuration) {
1857 assert_eq!(one, other);
1858 }
1859
1860 #[test_case(
1861 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1862 TimerDuration::new(zx::BootDuration::from_nanos(1), 2)
1863 )]
1864 #[test_case(
1865 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1866 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1867 )]
1868 fn test_slack_lt(one: TimerDuration, other: TimerDuration) {
1869 assert_lt!(one, other);
1870 }
1871
1872 #[test_case(
1873 TimerDuration::new(zx::BootDuration::from_nanos(1), 2),
1874 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1875 )]
1876 #[test_case(
1877 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1878 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1879 )]
1880 fn test_slack_gt(one: TimerDuration, other: TimerDuration) {
1881 assert_gt!(one, other);
1882 }
1883
1884 #[test_case(
1885 vec![zx::BootDuration::from_nanos(1)],
1886 100,
1887 zx::BootDuration::from_nanos(0),
1888 TimerDuration::new(zx::BootDuration::from_nanos(1), 1) ; "0ns becomes 1ns"
1889 )]
1890 #[test_case(
1891 vec![zx::BootDuration::from_nanos(1)],
1892 100,
1893 zx::BootDuration::from_nanos(50),
1894 TimerDuration::new(zx::BootDuration::from_nanos(1), 50) ; "Exact at 50x1ns"
1895 )]
1896 #[test_case(
1897 vec![zx::BootDuration::from_nanos(2)],
1898 100,
1899 zx::BootDuration::from_nanos(50),
1900 TimerDuration::new(zx::BootDuration::from_nanos(2), 25) ; "Exact at 25x2ns"
1901 )]
1902 #[test_case(
1903 vec![zx::BootDuration::from_nanos(3)],
1904 100,
1905 zx::BootDuration::from_nanos(50),
1906 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "Inexact at 51ns"
1908 )]
1909 #[test_case(
1910 vec![
1911 zx::BootDuration::from_nanos(3),
1912 zx::BootDuration::from_nanos(4)
1913 ],
1914 100,
1915 zx::BootDuration::from_nanos(50),
1916 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "3ns is a better resolution"
1917 )]
1918 #[test_case(
1919 vec![
1920 zx::BootDuration::from_nanos(1000),
1921 ],
1922 100,
1923 zx::BootDuration::from_nanos(50),
1924 TimerDuration::new(zx::BootDuration::from_nanos(1000), 1) ;
1925 "950ns negative slack is the best we can do"
1926 )]
1927 #[test_case(
1928 vec![
1929 zx::BootDuration::from_nanos(1),
1930 ],
1931 10,
1932 zx::BootDuration::from_nanos(50),
1933 TimerDuration::new(zx::BootDuration::from_nanos(1), 10) ;
1934 "10ns positive slack is the best we can do"
1935 )]
1936 #[test_case(
1937 vec![
1938 zx::BootDuration::from_millis(1),
1939 zx::BootDuration::from_micros(100),
1940 zx::BootDuration::from_micros(10),
1941 zx::BootDuration::from_micros(1),
1942 ],
1943 20, zx::BootDuration::from_micros(150),
1945 TimerDuration::new(zx::BootDuration::from_micros(10), 15) ;
1946 "Realistic case with resolutions from driver, should be 15us"
1947 )]
1948 #[test_case(
1949 vec![
1950 zx::BootDuration::from_millis(1),
1951 zx::BootDuration::from_micros(100),
1952 zx::BootDuration::from_micros(10),
1953 zx::BootDuration::from_micros(1),
1954 ],
1955 2000, zx::BootDuration::from_micros(6000),
1957 TimerDuration::new(zx::BootDuration::from_millis(1), 6) ;
1958 "Coarser exact unit wins"
1959 )]
1960 #[test_case(
1961 vec![
1962 zx::BootDuration::from_millis(1),
1963 zx::BootDuration::from_millis(10),
1964 zx::BootDuration::from_millis(100),
1965 ],
1966 1000,
1967 zx::BootDuration::from_micros(-10),
1968 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
1969 "Negative duration gets the smallest timer duration"
1970 )]
1971 #[test_case(
1972 vec![
1973 zx::BootDuration::from_millis(1),
1974 zx::BootDuration::from_millis(10),
1975 zx::BootDuration::from_millis(100),
1976 ],
1977 1000,
1978 zx::BootDuration::ZERO,
1979 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
1980 "Zero duration gets the smallest timer duration"
1981 )]
1982 fn test_pick_setting(
1983 resolutions: Vec<zx::BootDuration>,
1984 max_ticks: u64,
1985 duration: zx::BootDuration,
1986 expected: TimerDuration,
1987 ) {
1988 let config = TimerConfig::new_from_data(MAIN_TIMER_ID as u64, &resolutions[..], max_ticks);
1989 let actual = config.pick_setting(duration);
1990
1991 assert_slack_eq(expected, actual);
1994 }
1995
1996 fn assert_slack_eq(expected: TimerDuration, actual: TimerDuration) {
1998 let slack = expected.duration() - actual.duration();
1999 assert_eq!(
2000 actual.resolution(),
2001 expected.resolution(),
2002 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2003 expected,
2004 format_duration(expected.duration()),
2005 actual,
2006 format_duration(actual.duration()),
2007 format_duration(slack)
2008 );
2009 assert_eq!(
2010 actual.ticks(),
2011 expected.ticks(),
2012 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2013 expected,
2014 format_duration(expected.duration()),
2015 actual,
2016 format_duration(actual.duration()),
2017 format_duration(slack)
2018 );
2019 }
2020
2021 #[derive(Debug)]
2022 enum FakeCmd {
2023 SetProperties {
2024 resolutions: Vec<zx::BootDuration>,
2025 max_ticks: i64,
2026 keep_alive: zx::EventPair,
2027 done: zx::Event,
2028 },
2029 }
2030
2031 use std::cell::RefCell;
2032 use std::rc::Rc;
2033
2034 fn fake_hrtimer_connection(
2040 scope: fasync::ScopeHandle,
2041 rcv: mpsc::Receiver<FakeCmd>,
2042 ) -> ffhh::DeviceProxy {
2043 debug!("fake_hrtimer_connection: entry.");
2044 let (hrtimer, mut stream) =
2045 fidl::endpoints::create_proxy_and_stream::<ffhh::DeviceMarker>();
2046 scope.clone().spawn_local(async move {
2047 let mut rcv = rcv.fuse();
2048 let timer_properties = Rc::new(RefCell::new(None));
2049 let wake_lease = Rc::new(RefCell::new(None));
2050
2051 let timer_running = Rc::new(RefCell::new(false));
2055
2056 loop {
2057 let timer_properties = timer_properties.clone();
2058 let wake_lease = wake_lease.clone();
2059 select! {
2060 cmd = rcv.next() => {
2061 debug!("fake_hrtimer_connection: cmd: {:?}", cmd);
2062 match cmd {
2063 Some(FakeCmd::SetProperties{ resolutions, max_ticks, keep_alive, done}) => {
2064 let mut timer_props = vec![];
2065 for v in 0..10 {
2066 timer_props.push(ffhh::TimerProperties {
2067 supported_resolutions: Some(
2068 resolutions.iter()
2069 .map(|d| ffhh::Resolution::Duration(d.into_nanos())).collect()),
2070 max_ticks: Some(max_ticks.try_into().unwrap()),
2071 supports_wait: Some(true),
2073 id: Some(v),
2074 ..Default::default()
2075 },
2076 );
2077 }
2078 *timer_properties.borrow_mut() = Some(timer_props);
2079 *wake_lease.borrow_mut() = Some(keep_alive);
2080 debug!("set timer properties to: {:?}", timer_properties);
2081 signal(&done);
2082 }
2083 e => {
2084 panic!("unrecognized command: {:?}", e);
2085 }
2086 }
2087 },
2089 event = stream.next() => {
2090 debug!("fake_hrtimer_connection: event: {:?}", event);
2091 if let Some(Ok(event)) = event {
2092 match event {
2093 ffhh::DeviceRequest::Start { responder, .. } => {
2094 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2095 *timer_running.borrow_mut() = true;
2096 responder.send(Ok(())).expect("");
2097 }
2098 ffhh::DeviceRequest::Stop { responder, .. } => {
2099 *timer_running.borrow_mut() = false;
2100 responder.send(Ok(())).expect("");
2101 }
2102 ffhh::DeviceRequest::GetTicksLeft { responder, .. } => {
2103 responder.send(Ok(1)).expect("");
2104 }
2105 ffhh::DeviceRequest::SetEvent { responder, .. } => {
2106 responder.send(Ok(())).expect("");
2107 }
2108 ffhh::DeviceRequest::StartAndWait { id, resolution, ticks, setup_event, responder, .. } => {
2109 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2110 *timer_running.borrow_mut() = true;
2111 debug!("fake_hrtimer_connection: starting timer: \"{}\", resolution: {:?}, ticks: {}", id, resolution, ticks);
2112 let ticks: i64 = ticks.try_into().unwrap();
2113 let sleep_duration = zx::BootDuration::from_nanos(ticks * match resolution {
2114 ffhh::Resolution::Duration(e) => e,
2115 _ => {
2116 error!("resolution has an unexpected value");
2117 1
2118 }
2119 });
2120 let timer_running_clone = timer_running.clone();
2121 scope.spawn_local(async move {
2122 signal(&setup_event);
2125
2126 fasync::Timer::new(sleep_duration).await;
2129 *timer_running_clone.borrow_mut() = false;
2130 responder.send(Ok(wake_lease.borrow().as_ref().unwrap().duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap())).unwrap();
2131 debug!("StartAndWait: hrtimer expired");
2132 });
2133 }
2134 ffhh::DeviceRequest::StartAndWait2 { responder, .. } => {
2135 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2136 *timer_running.borrow_mut() = true;
2137 responder.send(Err(ffhh::DriverError::InternalError)).expect("");
2138 }
2139 ffhh::DeviceRequest::GetProperties { responder, .. } => {
2140 if (*timer_properties).borrow().is_none() {
2141 error!("timer_properties is empty, this is not what you want!");
2142 }
2143 responder
2144 .send(ffhh::Properties {
2145 timers_properties: (*timer_properties).borrow().clone(),
2146 ..Default::default()
2147 })
2148 .expect("");
2149 }
2150 ffhh::DeviceRequest::ReadTimer { responder, .. } => {
2151 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2152 }
2153 ffhh::DeviceRequest::ReadClock { responder, .. } => {
2154 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2155 }
2156 ffhh::DeviceRequest::_UnknownMethod { .. } => todo!(),
2157 }
2158 }
2159 },
2160 }
2161 }
2162 });
2163 hrtimer
2164 }
2165
2166 fn clone_utc_clock(orig: &fxr::UtcClock) -> fxr::UtcClock {
2167 orig.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2168 }
2169
2170 struct TestContext {
2171 wake_proxy: fta::WakeAlarmsProxy,
2172 _scope: fasync::Scope,
2173 _cmd_tx: mpsc::Sender<FakeCmd>,
2174 utc_clock: fxr::UtcClock,
2176 utc_backstop: fxr::UtcInstant,
2177 }
2178
2179 impl TestContext {
2180 async fn new() -> Self {
2181 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(0)).await;
2182
2183 let scope = fasync::Scope::new();
2184 let utc_backstop = fxr::UtcInstant::from_nanos(1000);
2185 let utc_clock =
2186 fxr::UtcClock::create(zx::ClockOpts::empty(), Some(utc_backstop)).unwrap();
2187 let utc_clone = clone_utc_clock(&utc_clock);
2188 let (mut cmd_tx, wake_proxy) = {
2189 let (tx, rx) = mpsc::channel::<FakeCmd>(0);
2190 let hrtimer_proxy = fake_hrtimer_connection(scope.to_handle(), rx);
2191
2192 let inspector = finspect::component::inspector();
2193 let alarms = Rc::new(Loop::new(
2194 scope.to_handle(),
2195 hrtimer_proxy,
2196 inspector.root().create_child("test"),
2197 utc_clone,
2198 ));
2199
2200 let (proxy, stream) =
2201 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2202 scope.spawn_local(async move {
2203 serve(alarms, stream).await;
2204 });
2205 (tx, proxy)
2206 };
2207
2208 let (_wake_lease, peer) = zx::EventPair::create();
2209 let done = zx::Event::create();
2210 cmd_tx
2211 .start_send(FakeCmd::SetProperties {
2212 resolutions: vec![zx::Duration::from_nanos(1)],
2213 max_ticks: 100,
2214 keep_alive: peer,
2215 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2216 })
2217 .unwrap();
2218
2219 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
2221
2222 Self { wake_proxy, _scope: scope, _cmd_tx: cmd_tx, utc_clock, utc_backstop }
2223 }
2224 }
2225
2226 impl Drop for TestContext {
2227 fn drop(&mut self) {
2228 assert_matches!(TestExecutor::next_timer(), None, "Unexpected lingering timers");
2229 }
2230 }
2231
2232 #[fuchsia::test(allow_stalls = false)]
2233 async fn test_basic_timed_wait() {
2234 let ctx = TestContext::new().await;
2235
2236 let deadline = zx::BootInstant::from_nanos(100);
2237 let setup_done = zx::Event::create();
2238 let mut set_task = ctx.wake_proxy.set_and_wait(
2239 deadline.into(),
2240 fta::SetMode::NotifySetupDone(
2241 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2242 ),
2243 "Hello".into(),
2244 );
2245
2246 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
2247
2248 let mut setup_done_task =
2249 pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2250 assert_matches!(
2251 TestExecutor::poll_until_stalled(&mut setup_done_task).await,
2252 Poll::Ready(Ok(_)),
2253 "Setup event not triggered after scheduling an alarm"
2254 );
2255
2256 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(100)).await;
2257 assert_matches!(TestExecutor::poll_until_stalled(set_task).await, Poll::Ready(Ok(Ok(_))));
2258 }
2259
2260 #[fuchsia::test(allow_stalls = false)]
2261 async fn test_basic_timed_wait_notify() {
2262 const ALARM_ID: &str = "Hello";
2263 let ctx = TestContext::new().await;
2264
2265 let (notifier_client, mut notifier_stream) =
2266 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2267 let setup_done = zx::Event::create();
2268 assert_matches!(
2269 ctx.wake_proxy
2270 .set(
2271 notifier_client,
2272 fidl::BootInstant::from_nanos(2),
2273 fta::SetMode::NotifySetupDone(
2274 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2275 ),
2276 ALARM_ID,
2277 )
2278 .await,
2279 Ok(Ok(()))
2280 );
2281
2282 let mut done_task = pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2283 assert_matches!(
2284 TestExecutor::poll_until_stalled(&mut done_task).await,
2285 Poll::Ready(Ok(_)),
2286 "Setup event not triggered after scheduling an alarm"
2287 );
2288
2289 let mut next_task = notifier_stream.next();
2290 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2291
2292 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2293 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2294
2295 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(2)).await;
2296 assert_matches!(
2297 TestExecutor::poll_until_stalled(next_task).await,
2298 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2299 );
2300 }
2301
2302 #[fuchsia::test(allow_stalls = false)]
2303 async fn test_two_alarms_same() {
2304 const DEADLINE_NANOS: i64 = 100;
2305
2306 let ctx = TestContext::new().await;
2307
2308 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2309 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2310 fta::SetMode::KeepAlive(fake_wake_lease()),
2311 "Hello1".into(),
2312 );
2313 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2314 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2315 fta::SetMode::KeepAlive(fake_wake_lease()),
2316 "Hello2".into(),
2317 );
2318
2319 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2320 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2321
2322 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2323
2324 assert_matches!(
2325 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2326 Poll::Ready(Ok(Ok(_)))
2327 );
2328 assert_matches!(
2329 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2330 Poll::Ready(Ok(Ok(_)))
2331 );
2332 }
2333
2334 #[fuchsia::test(allow_stalls = false)]
2335 async fn test_two_alarms_same_notify() {
2336 const DEADLINE_NANOS: i64 = 100;
2337 const ALARM_ID_1: &str = "Hello1";
2338 const ALARM_ID_2: &str = "Hello2";
2339
2340 let ctx = TestContext::new().await;
2341
2342 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2343 let (notifier_client, notifier_stream) =
2344 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2345 assert_matches!(
2346 ctx.wake_proxy
2347 .set(
2348 notifier_client,
2349 fidl::BootInstant::from_nanos(deadline_nanos),
2350 fta::SetMode::KeepAlive(fake_wake_lease()),
2351 alarm_id,
2352 )
2353 .await,
2354 Ok(Ok(()))
2355 );
2356 notifier_stream
2357 };
2358
2359 let mut notifier_1 = schedule(DEADLINE_NANOS, ALARM_ID_1).await;
2360 let mut notifier_2 = schedule(DEADLINE_NANOS, ALARM_ID_2).await;
2361
2362 let mut next_task_1 = notifier_1.next();
2363 let mut next_task_2 = notifier_2.next();
2364
2365 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2366 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2367
2368 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2369
2370 assert_matches!(
2371 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2372 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_1
2373 );
2374 assert_matches!(
2375 TestExecutor::poll_until_stalled(&mut next_task_2).await,
2376 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_2
2377 );
2378
2379 assert_matches!(
2380 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2381 Poll::Ready(None)
2382 );
2383 assert_matches!(
2384 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2385 Poll::Ready(None)
2386 );
2387 }
2388
2389 #[test_case(100, 200 ; "push out")]
2390 #[test_case(200, 100 ; "pull in")]
2391 #[fuchsia::test(allow_stalls = false)]
2392 async fn test_two_alarms_different(
2393 first_deadline_nanos: i64,
2395 second_deadline_nanos: i64,
2397 ) {
2398 let ctx = TestContext::new().await;
2399
2400 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2401 fidl::BootInstant::from_nanos(first_deadline_nanos),
2402 fta::SetMode::KeepAlive(fake_wake_lease()),
2403 "Hello1".into(),
2404 );
2405 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2406 fidl::BootInstant::from_nanos(second_deadline_nanos),
2407 fta::SetMode::KeepAlive(fake_wake_lease()),
2408 "Hello2".into(),
2409 );
2410
2411 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2412 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2413
2414 let mut tasks = [(first_deadline_nanos, set_task_1), (second_deadline_nanos, set_task_2)];
2416 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2417 let [mut first_task, mut second_task] = tasks;
2418
2419 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(first_task.0)).await;
2421 assert_matches!(
2422 TestExecutor::poll_until_stalled(&mut first_task.1).await,
2423 Poll::Ready(Ok(Ok(_)))
2424 );
2425 assert_matches!(TestExecutor::poll_until_stalled(&mut second_task.1).await, Poll::Pending);
2426
2427 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(second_task.0)).await;
2428 assert_matches!(
2429 TestExecutor::poll_until_stalled(&mut second_task.1).await,
2430 Poll::Ready(Ok(Ok(_)))
2431 );
2432 }
2433
2434 #[test_case(100, 200 ; "push out")]
2435 #[test_case(200, 100 ; "pull in")]
2436 #[fuchsia::test(allow_stalls = false)]
2437 async fn test_two_alarms_different_notify(
2438 first_deadline_nanos: i64,
2440 second_deadline_nanos: i64,
2442 ) {
2443 const ALARM_ID_1: &str = "Hello1";
2444 const ALARM_ID_2: &str = "Hello2";
2445
2446 let ctx = TestContext::new().await;
2447
2448 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2449 let (notifier_client, notifier_stream) =
2450 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2451 assert_matches!(
2452 ctx.wake_proxy
2453 .set(
2454 notifier_client,
2455 fidl::BootInstant::from_nanos(deadline_nanos),
2456 fta::SetMode::KeepAlive(fake_wake_lease()),
2457 alarm_id,
2458 )
2459 .await,
2460 Ok(Ok(()))
2461 );
2462 notifier_stream
2463 };
2464
2465 let mut notifier_all = futures::stream::select_all([
2467 schedule(first_deadline_nanos, ALARM_ID_1).await,
2468 schedule(second_deadline_nanos, ALARM_ID_2).await,
2469 ]);
2470 let [(early_ns, early_alarm), (later_ns, later_alarm)] = {
2471 let mut tasks =
2472 [(first_deadline_nanos, ALARM_ID_1), (second_deadline_nanos, ALARM_ID_2)];
2473 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2474 tasks
2475 };
2476
2477 let mut next_task = notifier_all.next();
2479 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2480
2481 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(early_ns)).await;
2482 assert_matches!(
2483 TestExecutor::poll_until_stalled(next_task).await,
2484 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == early_alarm
2485 );
2486
2487 let mut next_task = notifier_all.next();
2488 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2489
2490 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(later_ns)).await;
2491 assert_matches!(
2492 TestExecutor::poll_until_stalled(next_task).await,
2493 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == later_alarm
2494 );
2495 assert_matches!(
2496 TestExecutor::poll_until_stalled(notifier_all.next()).await,
2497 Poll::Ready(None)
2498 );
2499 }
2500
2501 #[fuchsia::test(allow_stalls = false)]
2502 async fn test_alarm_immediate() {
2503 let ctx = TestContext::new().await;
2504 let mut set_task = ctx.wake_proxy.set_and_wait(
2505 fidl::BootInstant::INFINITE_PAST,
2506 fta::SetMode::KeepAlive(fake_wake_lease()),
2507 "Hello1".into(),
2508 );
2509 assert_matches!(
2510 TestExecutor::poll_until_stalled(&mut set_task).await,
2511 Poll::Ready(Ok(Ok(_)))
2512 );
2513 }
2514
2515 #[fuchsia::test(allow_stalls = false)]
2516 async fn test_alarm_immediate_notify() {
2517 const ALARM_ID: &str = "Hello";
2518 let ctx = TestContext::new().await;
2519
2520 let (notifier_client, mut notifier_stream) =
2521 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2522
2523 let mut set_task = ctx.wake_proxy.set(
2524 notifier_client,
2525 fidl::BootInstant::INFINITE_PAST,
2526 fta::SetMode::KeepAlive(fake_wake_lease()),
2527 ALARM_ID,
2528 );
2529 assert_matches!(
2530 TestExecutor::poll_until_stalled(&mut set_task).await,
2531 Poll::Ready(Ok(Ok(_)))
2532 );
2533 assert_matches!(
2534 TestExecutor::poll_until_stalled(notifier_stream.next()).await,
2535 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2536 );
2537 }
2538
2539 #[test_case(200, 100 ; "pull in")]
2542 #[test_case(100, 200 ; "push out")]
2543 #[test_case(100, 100 ; "replace with the same deadline")]
2544 #[fuchsia::test(allow_stalls = false)]
2545 async fn test_reschedule(initial_deadline_nanos: i64, override_deadline_nanos: i64) {
2546 const ALARM_ID: &str = "Hello";
2547
2548 let ctx = TestContext::new().await;
2549
2550 let schedule = |deadline_nanos: i64| {
2551 let setup_done = zx::Event::create();
2552 let task = ctx.wake_proxy.set_and_wait(
2553 fidl::BootInstant::from_nanos(deadline_nanos),
2554 fta::SetMode::NotifySetupDone(
2555 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2556 ),
2557 ALARM_ID.into(),
2558 );
2559 (task, setup_done)
2560 };
2561
2562 let (mut set_task_1, setup_done_1) = schedule(initial_deadline_nanos);
2565 fasync::OnSignals::new(setup_done_1, zx::Signals::EVENT_SIGNALED).await.unwrap();
2566 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2567
2568 let (mut set_task_2, setup_done_2) = schedule(override_deadline_nanos);
2571 fasync::OnSignals::new(setup_done_2, zx::Signals::EVENT_SIGNALED).await.unwrap();
2572 assert_matches!(
2573 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2574 Poll::Ready(Ok(Err(fta::WakeAlarmsError::Dropped)))
2575 );
2576 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2577
2578 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos - 1))
2580 .await;
2581 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2582 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos))
2583 .await;
2584 assert_matches!(
2585 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2586 Poll::Ready(Ok(Ok(_)))
2587 );
2588
2589 assert_data_tree!(finspect::component::inspector(), root: {
2592 test: {
2593 hardware: {
2594 current_deadline: "(none)",
2596 remaining_until_alarm: "(none)",
2597 },
2598 now_formatted: format!("{override_deadline_nanos}ns ({override_deadline_nanos})"),
2599 now_ns: override_deadline_nanos,
2600 pending_timers: "Boot:\n\t\n\tUTC:\n\t",
2601 pending_timers_count: 0u64,
2602 requested_deadlines_ns: AnyProperty,
2603 schedule_delay_ns: AnyProperty,
2604 slack_ns: AnyProperty,
2605 boot_deadlines_count: AnyProperty,
2606 utc_deadlines_count: AnyProperty,
2607 debug_node: contains {},
2608 },
2609 });
2610 }
2611
2612 #[fuchsia::test(allow_stalls = false)]
2615 async fn test_reschedule_notify() {
2616 const ALARM_ID: &str = "Hello";
2617 const INITIAL_DEADLINE_NANOS: i64 = 100;
2618 const OVERRIDE_DEADLINE_NANOS: i64 = 200;
2619
2620 let ctx = TestContext::new().await;
2621
2622 let schedule = async |deadline_nanos: i64| {
2623 let (notifier_client, notifier_stream) =
2624 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2625 assert_matches!(
2626 ctx.wake_proxy
2627 .set(
2628 notifier_client,
2629 fidl::BootInstant::from_nanos(deadline_nanos),
2630 fta::SetMode::KeepAlive(fake_wake_lease()),
2631 ALARM_ID.into(),
2632 )
2633 .await,
2634 Ok(Ok(()))
2635 );
2636 notifier_stream
2637 };
2638
2639 let mut notifier_1 = schedule(INITIAL_DEADLINE_NANOS).await;
2640 let mut next_task_1 = notifier_1.next();
2641 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2642
2643 let mut notifier_2 = schedule(OVERRIDE_DEADLINE_NANOS).await;
2644 let mut next_task_2 = notifier_2.next();
2645 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2646
2647 assert_matches!(
2649 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2650 Poll::Ready(Some(Ok(fta::NotifierRequest::NotifyError { alarm_id, error, .. }))) if alarm_id == ALARM_ID && error == fta::WakeAlarmsError::Dropped
2651 );
2652 assert_matches!(
2653 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2654 Poll::Ready(None)
2655 );
2656
2657 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(OVERRIDE_DEADLINE_NANOS))
2659 .await;
2660 assert_matches!(
2661 TestExecutor::poll_until_stalled(next_task_2).await,
2662 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2663 );
2664 assert_matches!(
2665 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2666 Poll::Ready(None)
2667 );
2668 }
2669
2670 #[fuchsia::test(allow_stalls = false)]
2673 async fn test_fidl_error_on_reschedule() {
2674 const DEADLINE_NANOS: i64 = 100;
2675
2676 let (wake_proxy, _stream) =
2677 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2678 drop(_stream);
2679
2680 assert_matches!(
2681 wake_proxy
2682 .set_and_wait(
2683 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2684 fta::SetMode::KeepAlive(fake_wake_lease()),
2685 "hello1".into(),
2686 )
2687 .await,
2688 Err(fidl::Error::ClientChannelClosed { .. })
2689 );
2690
2691 assert_matches!(
2692 wake_proxy
2693 .set_and_wait(
2694 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2695 fta::SetMode::KeepAlive(fake_wake_lease()),
2696 "hello2".into(),
2697 )
2698 .await,
2699 Err(fidl::Error::ClientChannelClosed { .. })
2700 );
2701 }
2702
2703 #[fuchsia::test(allow_stalls = false)]
2706 async fn test_set_and_wait_utc() {
2707 const ALARM_ID: &str = "Hello_set_and_wait_utc";
2708 let ctx = TestContext::new().await;
2709
2710 let now_boot = fasync::BootInstant::now();
2711 ctx.utc_clock
2712 .update(
2713 zx::ClockUpdate::builder()
2714 .absolute_value(now_boot.into(), ctx.utc_backstop)
2715 .build(),
2716 )
2717 .unwrap();
2718
2719 let timestamp_utc = ctx.utc_backstop + fxr::UtcDuration::from_nanos(2);
2720 let mut wake_fut = ctx.wake_proxy.set_and_wait_utc(
2721 &fta::InstantUtc { timestamp_utc: timestamp_utc.into_nanos() },
2722 fta::SetMode::KeepAlive(fake_wake_lease()),
2723 ALARM_ID,
2724 );
2725
2726 assert_matches!(TestExecutor::poll_until_stalled(&mut wake_fut).await, Poll::Pending);
2728
2729 ctx.utc_clock
2731 .update(
2732 zx::ClockUpdate::builder()
2733 .absolute_value(
2734 now_boot.into(),
2735 ctx.utc_backstop + fxr::UtcDuration::from_nanos(100),
2736 )
2737 .build(),
2738 )
2739 .unwrap();
2740
2741 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2743 assert_matches!(TestExecutor::poll_until_stalled(wake_fut).await, Poll::Ready(_));
2744 }
2745}