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().saturating_mul(self.ticks);
855 let clamp_duration = std::cmp::min(*I64_MAX_AS_U64, duration_as_nanos);
856 zx::BootDuration::from_nanos(clamp_duration.try_into().expect("clamp_duration fits in i64"))
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 has_finer_resolution =
1021 self.resolutions.iter().any(|&res| res < best_positive_slack.resolution());
1022 let ret = if best_negative_slack == TimerDuration::max()
1023 || (best_positive_slack.duration() > zx::BootDuration::ZERO
1024 && (has_finer_resolution || best_positive_slack.ticks() == self.max_ticks)
1025 && p_slack < n_slack)
1026 {
1027 best_positive_slack
1028 } else {
1029 best_negative_slack
1030 };
1031 debug!("TimerConfig: picked slack: {} for duration: {}", ret, format_duration(duration));
1032 assert!(
1033 ret.duration().into_nanos() >= 0,
1034 "ret: {}, p_slack: {}, n_slack: {}, orig.duration: {}\n\tbest_p_slack: {}\n\tbest_n_slack: {}\n\ttarget: {}\n\t 1: {} 2: {:?}, 3: {:?}",
1035 ret,
1036 format_duration(p_slack),
1037 format_duration(n_slack),
1038 format_duration(duration),
1039 best_positive_slack,
1040 best_negative_slack,
1041 duration_slack,
1042 p_slack != zx::BootDuration::ZERO,
1043 p_slack,
1044 zx::BootDuration::ZERO,
1045 );
1046 ret
1047 }
1048}
1049
1050async fn get_timer_properties(hrtimer: &Box<dyn TimerOps>) -> TimerConfig {
1051 debug!("get_timer_properties: requesting timer properties.");
1052 hrtimer.get_timer_properties().await
1053}
1054
1055struct TimerState {
1057 task: fasync::Task<()>,
1059 deadline: fasync::BootInstant,
1061}
1062
1063async fn wake_timer_loop(
1072 scope: fasync::ScopeHandle,
1073 snd: mpsc::Sender<Cmd>,
1074 mut cmds: mpsc::Receiver<Cmd>,
1075 timer_proxy: Box<dyn TimerOps>,
1076 inspect: finspect::Node,
1077 utc_transform: Rc<RefCell<fxr::UtcClockTransform>>,
1078) {
1079 debug!("wake_timer_loop: started");
1080
1081 let mut timers = timers::Heap::new(utc_transform.clone());
1082 let timer_config = get_timer_properties(&timer_proxy).await;
1083
1084 #[allow(clippy::collection_is_never_read)]
1087 let mut hrtimer_status: Option<TimerState> = None;
1088
1089 let now_prop = inspect.create_int("now_ns", 0);
1096 let now_formatted_prop = inspect.create_string("now_formatted", "");
1097 let pending_timers_count_prop = inspect.create_uint("pending_timers_count", 0);
1098 let pending_timers_prop = inspect.create_string("pending_timers", "");
1099 let _deadline_histogram_prop = inspect.create_int_exponential_histogram(
1100 "requested_deadlines_ns",
1101 finspect::ExponentialHistogramParams {
1102 floor: 0,
1103 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1104 step_multiplier: 10,
1106 buckets: 16,
1107 },
1108 );
1109 let slack_histogram_prop = inspect.create_int_exponential_histogram(
1110 "slack_ns",
1111 finspect::ExponentialHistogramParams {
1112 floor: 0,
1113 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1114 step_multiplier: 10,
1115 buckets: 16,
1116 },
1117 );
1118 let schedule_delay_prop = inspect.create_int_exponential_histogram(
1119 "schedule_delay_ns",
1120 finspect::ExponentialHistogramParams {
1121 floor: 0,
1122 initial_step: zx::BootDuration::from_micros(1).into_nanos(),
1123 step_multiplier: 10,
1124 buckets: 16,
1125 },
1126 );
1127 let boot_deadlines_count_prop = inspect.create_uint("boot_deadlines_count", 0);
1128 let utc_deadlines_count_prop = inspect.create_uint("utc_deadlines_count", 0);
1129 let hw_node = inspect.create_child("hardware");
1131 let current_hw_deadline_prop = hw_node.create_string("current_deadline", "");
1132 let remaining_until_alarm_prop = hw_node.create_string("remaining_until_alarm", "");
1133
1134 let debug_node = inspect.create_child("debug_node");
1136 let start_notify_setup_count = debug_node.create_int("start_notify_setup", 0);
1137 let start_count = debug_node.create_int("start_count", 0);
1138 let responder_count = debug_node.create_int("responder_count", 0);
1139 let stop_count = debug_node.create_int("stop", 0);
1140 let stop_responder_count = debug_node.create_int("stop_responder", 0);
1141 let stop_hrtimer_count = debug_node.create_int("stop_hrtimer", 0);
1142 let schedule_hrtimer_count = debug_node.create_int("schedule_hrtimer", 0);
1143 let alarm_count = debug_node.create_int("alarm", 0);
1144 let alarm_fidl_count = debug_node.create_int("alarm_fidl", 0);
1145 let alarm_driver_count = debug_node.create_int("alarm_driver", 0);
1146 let utc_update_count = debug_node.create_int("utc_update", 0);
1147 let status_count = debug_node.create_int("status", 0);
1148 let loop_count = debug_node.create_int("loop_count", 0);
1149
1150 let hrtimer_node = debug_node.create_child("hrtimer");
1151
1152 const LRU_CACHE_CAPACITY: NonZeroUsize = NonZeroUsize::new(100).unwrap();
1153 let mut error_cache = lru::LruCache::new(LRU_CACHE_CAPACITY);
1154
1155 while let Some(cmd) = cmds.next().await {
1156 let _i = ScopedInc::new(&loop_count);
1157 trace::duration!("alarms", "Cmd");
1158 let now = fasync::BootInstant::now();
1160 now_prop.set(now.into_nanos());
1161 trace::instant!("alarms", "wake_timer_loop", trace::Scope::Process, "now" => now.into_nanos());
1162 match cmd {
1163 Cmd::Start { conn_id, deadline, mode, alarm_id, responder } => {
1164 let _i = ScopedInc::new(&start_count);
1165 trace::duration!("alarms", "Cmd::Start");
1166 fuchsia_trace::flow_step!(
1167 "alarms",
1168 "hrtimer_lifecycle",
1169 timers::get_trace_id(&alarm_id)
1170 );
1171 debug!(
1173 "wake_timer_loop: START alarm_id: \"{}\", conn_id: {:?}\n\tdeadline: {}\n\tnow: {}",
1174 alarm_id,
1175 conn_id,
1176 deadline,
1177 format_timer(now.into()),
1178 );
1179
1180 defer! {
1181 let _i = ScopedInc::new(&start_notify_setup_count);
1182 if let Some(fta::SetMode::NotifySetupDone(ref setup_done)) = mode {
1184 signal(setup_done);
1186 debug!("wake_timer_loop: START: setup_done signaled");
1187 }
1188 }
1189 let deadline_boot = deadline.as_boot(&*utc_transform.borrow());
1190
1191 match deadline {
1195 timers::Deadline::Boot(_) => boot_deadlines_count_prop.add(1),
1196 timers::Deadline::Utc(_) => utc_deadlines_count_prop.add(1),
1197 };
1198
1199 if timers::Heap::expired(now, deadline_boot) {
1200 trace::duration!("alarms", "Cmd::Start:immediate");
1201 fuchsia_trace::flow_step!(
1202 "alarms",
1203 "hrtimer_lifecycle",
1204 timers::get_trace_id(&alarm_id)
1205 );
1206 let (_lease, keep_alive) = zx::EventPair::create();
1208 debug!(
1209 "[{}] wake_timer_loop: bogus lease {:?}",
1210 line!(),
1211 keep_alive.koid().unwrap()
1212 );
1213
1214 {
1215 let _i1 = ScopedInc::new(&responder_count);
1216 if let Err(e) = responder
1217 .send(&alarm_id, Ok(keep_alive))
1218 .expect("responder is always present")
1219 {
1220 error!(
1221 "wake_timer_loop: conn_id: {conn_id:?}, alarm: {alarm_id}: could not notify, dropping: {e}",
1222 );
1223 } else {
1224 debug!(
1225 "wake_timer_loop: conn_id: {conn_id:?}, alarm: {alarm_id}: EXPIRED IMMEDIATELY\n\tdeadline({}) <= now({})\n\tfull deadline: {}",
1226 format_timer(deadline_boot.into()),
1227 format_timer(now.into()),
1228 deadline,
1229 )
1230 }
1231 }
1232 } else {
1233 trace::duration!("alarms", "Cmd::Start:regular");
1234 fuchsia_trace::flow_step!(
1235 "alarms",
1236 "hrtimer_lifecycle",
1237 timers::get_trace_id(&alarm_id)
1238 );
1239 let was_empty = timers.is_empty();
1241
1242 let deadline_before = timers.peek_deadline_as_boot();
1243 let node = match deadline {
1244 timers::Deadline::Boot(_) => {
1245 timers.new_node_boot(deadline_boot, alarm_id, conn_id, responder)
1246 }
1247 timers::Deadline::Utc(d) => {
1248 timers.new_node_utc(d, alarm_id, conn_id, responder)
1249 }
1250 };
1251 timers.push(node);
1252 let deadline_after = timers.peek_deadline_as_boot();
1253
1254 let deadline_changed = is_deadline_changed(deadline_before, deadline_after);
1255 let needs_cancel = !was_empty && deadline_changed;
1256 let needs_reschedule = was_empty || deadline_changed;
1257
1258 if needs_reschedule {
1259 if needs_cancel {
1260 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1261 }
1262 let (_dummy_lease, peer) = zx::EventPair::create();
1263 let lease_prototype = match &mode {
1264 Some(fta::SetMode::KeepAlive(lease)) => lease,
1265 _ => &peer,
1266 };
1267 hrtimer_status = reschedule_proximate_hrtimer(
1268 scope.clone(),
1269 &timer_proxy,
1270 &mut timers,
1271 snd.clone(),
1272 &timer_config,
1273 lease_prototype,
1274 false,
1275 &schedule_delay_prop,
1276 &slack_histogram_prop,
1277 &hrtimer_node,
1278 )
1279 .await;
1280 }
1281 }
1282 }
1283 Cmd::StopById { timer_id, done } => {
1284 let _i = ScopedInc::new(&stop_count);
1285 defer! {
1286 signal(&done);
1287 }
1288 trace::duration!("alarms", "Cmd::StopById", "alarm_id" => timer_id.alarm());
1289 fuchsia_trace::flow_step!(
1290 "alarms",
1291 "hrtimer_lifecycle",
1292 timers::get_trace_id(&timer_id.alarm())
1293 );
1294 debug!("wake_timer_loop: STOP timer: {}", timer_id);
1295 let deadline_before = timers.peek_deadline_as_boot();
1296
1297 if let Some(timer_node) = timers.remove_by_id(&timer_id) {
1298 let deadline_after = timers.peek_deadline_as_boot();
1299
1300 {
1301 let _i = ScopedInc::new(&stop_responder_count);
1302 if let Some(res) = timer_node
1303 .get_responder()
1304 .send(timer_node.id().alarm(), Err(fta::WakeAlarmsError::Dropped))
1305 {
1306 res.expect("infallible");
1308 }
1309 }
1310 if is_deadline_changed(deadline_before, deadline_after) {
1311 let _i = ScopedInc::new(&stop_hrtimer_count);
1312 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1313 let (_dummy_lease, peer) = zx::EventPair::create();
1316 if let Some(new_timer_state) = reschedule_proximate_hrtimer(
1319 scope.clone(),
1320 &timer_proxy,
1321 &mut timers,
1322 snd.clone(),
1323 &timer_config,
1324 &peer,
1325 false,
1326 &schedule_delay_prop,
1327 &slack_histogram_prop,
1328 &hrtimer_node,
1329 )
1330 .await
1331 {
1332 let _i = ScopedInc::new(&schedule_hrtimer_count);
1333 let old_hrtimer_status = hrtimer_status.replace(new_timer_state);
1334 if let Some(task) = old_hrtimer_status.map(|ev| ev.task) {
1335 log_long_op!(task);
1339 }
1340 } else {
1341 hrtimer_status = None;
1343 }
1344 }
1345 } else {
1346 debug!("wake_timer_loop: STOP: removed non-imminent timer: {}", timer_id);
1348 }
1349 }
1350 Cmd::Alarm { expired_deadline, keep_alive } => {
1351 let _i = ScopedInc::new(&alarm_count);
1352
1353 trace::duration!("alarms", "Cmd::Alarm");
1354 debug!(
1359 "wake_timer_loop: ALARM!!! reached deadline: {}, wakey-wakey! {:?}",
1360 format_timer(expired_deadline.into()),
1361 keep_alive.koid().unwrap(),
1362 );
1363 hrtimer_status = reschedule_proximate_hrtimer(
1365 scope.clone(),
1366 &timer_proxy,
1367 &mut timers,
1368 snd.clone(),
1369 &timer_config,
1370 &keep_alive,
1371 true,
1372 &schedule_delay_prop,
1373 &slack_histogram_prop,
1374 &hrtimer_node,
1375 )
1376 .await;
1377 }
1378 Cmd::AlarmFidlError { expired_deadline, error } => {
1379 let _i = ScopedInc::new(&alarm_fidl_count);
1380
1381 trace::duration!("alarms", "Cmd::AlarmFidlError");
1382 let error_string = format!("{}", error);
1386 if !error_cache.contains(&error_string) {
1387 warn!(
1388 "wake_timer_loop: FIDL error: {}, deadline: {}, now: {}",
1389 error,
1390 format_timer(expired_deadline.into()),
1391 format_timer(now.into()),
1392 );
1393 error_cache.put(error_string, ());
1394 }
1395 let (_dummy_lease, peer) = zx::EventPair::create();
1398 debug!(
1399 "bogus lease: {:?} fidl error [{}:{}]",
1400 peer.koid().unwrap(),
1401 file!(),
1402 line!()
1403 );
1404 notify_all(
1405 &mut timers,
1406 &peer,
1407 now,
1408 Some(TimerOpsError::Fidl(error)),
1409 &slack_histogram_prop,
1410 )
1411 .expect("notification succeeds");
1412 hrtimer_status = reschedule_proximate_hrtimer(
1413 scope.clone(),
1414 &timer_proxy,
1415 &mut timers,
1416 snd.clone(),
1417 &timer_config,
1418 &peer,
1419 false,
1420 &schedule_delay_prop,
1421 &slack_histogram_prop,
1422 &hrtimer_node,
1423 )
1424 .await;
1425 }
1426 Cmd::AlarmDriverError {
1427 expired_deadline,
1428 error,
1429 timer_config_id,
1430 resolution_nanos,
1431 ticks,
1432 } => {
1433 let _i = ScopedInc::new(&alarm_driver_count);
1434
1435 trace::duration!("alarms", "Cmd::AlarmDriverError");
1436 let (_dummy_lease, peer) = zx::EventPair::create();
1437 debug!(
1438 "bogus lease: {:?} driver error. [{}:{}]",
1439 peer.koid().unwrap(),
1440 file!(),
1441 line!()
1442 );
1443 notify_all(
1444 &mut timers,
1445 &peer,
1446 now,
1447 Some(TimerOpsError::Driver(error)),
1448 &slack_histogram_prop,
1449 )
1450 .expect("notification succeeds");
1451 match error {
1452 fidl_fuchsia_hardware_hrtimer::DriverError::Canceled => {
1453 debug!(
1455 "wake_timer_loop: CANCELED timer at deadline: {}",
1456 format_timer(expired_deadline.into())
1457 );
1458 }
1459 _ => {
1460 error!(
1461 "wake_timer_loop: DRIVER SAYS: {:?}, deadline: {}, now: {}\n\ttimer_id={}\n\tresolution={}\n\tticks={}",
1462 error,
1463 format_timer(expired_deadline.into()),
1464 format_timer(now.into()),
1465 timer_config_id,
1466 resolution_nanos,
1467 ticks,
1468 );
1469 hrtimer_status = reschedule_proximate_hrtimer(
1473 scope.clone(),
1474 &timer_proxy,
1475 &mut timers,
1476 snd.clone(),
1477 &timer_config,
1478 &peer,
1479 false,
1480 &schedule_delay_prop,
1481 &slack_histogram_prop,
1482 &hrtimer_node,
1483 )
1484 .await;
1485 }
1486 }
1487 }
1488 Cmd::UtcUpdated { transform } => {
1489 let _i = ScopedInc::new(&utc_update_count);
1490
1491 trace::duration!("alarms", "Cmd::UtcUpdated");
1492 debug!("wake_timer_loop: applying new clock transform: {transform:?}");
1493
1494 *utc_transform.borrow_mut() = transform;
1497
1498 if hrtimer_status.is_some() {
1501 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1502 let (_dummy_lease, peer) = zx::EventPair::create();
1506 hrtimer_status = reschedule_proximate_hrtimer(
1507 scope.clone(),
1508 &timer_proxy,
1509 &mut timers,
1510 snd.clone(),
1511 &timer_config,
1512 &peer,
1513 false,
1514 &schedule_delay_prop,
1515 &slack_histogram_prop,
1516 &hrtimer_node,
1517 )
1518 .await;
1519 }
1520 }
1521 }
1522
1523 {
1524 let _i = ScopedInc::new(&status_count);
1525
1526 trace::duration!("timekeeper", "inspect");
1531 let now_formatted = format_timer(now.into());
1532 debug!("wake_timer_loop: now: {}", now_formatted);
1533 now_formatted_prop.set(&now_formatted);
1534
1535 let pending_timers_count: u64 =
1536 timers.timer_count().try_into().expect("always convertible");
1537 debug!("wake_timer_loop: currently pending timer count: {}", pending_timers_count);
1538 pending_timers_count_prop.set(pending_timers_count);
1539
1540 let pending_timers = format!("{}", timers);
1541 debug!("wake_timer_loop: currently pending timers: \n\t{}", timers);
1542 pending_timers_prop.set(&pending_timers);
1543
1544 let current_deadline: String = hrtimer_status
1545 .as_ref()
1546 .map(|s| format!("{}", format_timer(s.deadline.into())))
1547 .unwrap_or_else(|| "(none)".into());
1548 debug!("wake_timer_loop: current hardware timer deadline: {:?}", current_deadline);
1549 current_hw_deadline_prop.set(¤t_deadline);
1550
1551 let remaining_duration_until_alarm = hrtimer_status
1552 .as_ref()
1553 .map(|s| format!("{}", format_duration((s.deadline - now).into())))
1554 .unwrap_or_else(|| "(none)".into());
1555 debug!(
1556 "wake_timer_loop: remaining duration until alarm: {}",
1557 remaining_duration_until_alarm
1558 );
1559 remaining_until_alarm_prop.set(&remaining_duration_until_alarm);
1560 debug!("---");
1561 }
1562 }
1563
1564 log::info!("wake_timer_loop: exiting. This is only correct in test code.");
1567}
1568
1569async fn reschedule_proximate_hrtimer(
1576 scope: fasync::ScopeHandle,
1577 timer_proxy: &Box<dyn TimerOps>,
1578 timers: &mut timers::Heap,
1579 snd: mpsc::Sender<Cmd>,
1580 timer_config: &TimerConfig,
1581 lease_prototype: &zx::EventPair,
1582 stop_if_no_expired: bool,
1583 schedule_delay_prop: &finspect::IntExponentialHistogramProperty,
1584 slack_histogram_prop: &finspect::IntExponentialHistogramProperty,
1585 hrtimer_node: &finspect::Node,
1586) -> Option<TimerState> {
1587 let mut stop_on_zero_expired = stop_if_no_expired;
1588 loop {
1589 let now = fasync::BootInstant::now();
1590 let expired_count = notify_all(timers, lease_prototype, now, None, slack_histogram_prop)
1591 .expect("notification succeeds");
1592 if std::mem::replace(&mut stop_on_zero_expired, false) && expired_count == 0 {
1593 debug!("wake_timer_loop: no expired alarms, reset hrtimer state");
1596 log_long_op!(stop_hrtimer(timer_proxy, timer_config));
1597 continue;
1598 }
1599
1600 let Some(deadline) = timers.peek_deadline_as_boot() else {
1601 return None;
1602 };
1603
1604 let state = schedule_hrtimer(
1605 scope.clone(),
1606 now,
1607 timer_proxy,
1608 deadline,
1609 snd.clone(),
1610 timer_config,
1611 schedule_delay_prop,
1612 hrtimer_node,
1613 )
1614 .await;
1615
1616 let now_after = fasync::BootInstant::now();
1617 if !timers::Heap::expired(now_after, deadline) {
1618 return Some(state);
1619 }
1620
1621 debug!(
1622 "reschedule_proximate_hrtimer: deadline {} expired during scheduling (now: {}), triggering immediately",
1623 format_timer(deadline.into()),
1624 format_timer(now_after.into()),
1625 );
1626 drop(state);
1629 log_long_op!(stop_hrtimer(timer_proxy, timer_config));
1630 }
1631}
1632
1633async fn schedule_hrtimer(
1647 scope: fasync::ScopeHandle,
1648 now: fasync::BootInstant,
1649 hrtimer: &Box<dyn TimerOps>,
1650 deadline: fasync::BootInstant,
1651 mut command_send: mpsc::Sender<Cmd>,
1652 timer_config: &TimerConfig,
1653 _schedule_delay_histogram: &finspect::IntExponentialHistogramProperty,
1654 debug_node: &finspect::Node,
1655) -> TimerState {
1656 let timeout = std::cmp::max(zx::BootDuration::ZERO, deadline - now);
1657 trace::duration!("alarms", "schedule_hrtimer", "timeout" => timeout.into_nanos());
1658 let hrtimer_scheduled = zx::Event::create();
1660
1661 let schedule_count = debug_node.create_int("schedule", 0);
1662 let hrtimer_wait_count = debug_node.create_int("hrtimer_wait", 0);
1663 let wait_signaled_count = debug_node.create_int("wait_signaled", 0);
1664
1665 let _sc = ScopedInc::new(&schedule_count);
1666
1667 debug!(
1668 "schedule_hrtimer:\n\tnow: {}\n\tdeadline: {}\n\ttimeout: {}",
1669 format_timer(now.into()),
1670 format_timer(deadline.into()),
1671 format_duration(timeout),
1672 );
1673
1674 let slack = timer_config.pick_setting(timeout);
1675 let resolution_nanos = slack.resolution.into_nanos();
1676 let useful_ticks = std::cmp::max(MIN_USEFUL_TICKS, slack.ticks());
1679
1680 trace::instant!("alarms", "hrtimer:programmed",
1681 trace::Scope::Process,
1682 "resolution_ns" => resolution_nanos,
1683 "ticks" => useful_ticks
1684 );
1685 let timer_config_id = timer_config.id;
1686 let start_and_wait_fut = {
1687 let _sc = ScopedInc::new(&hrtimer_wait_count);
1688 hrtimer.start_and_wait(
1689 timer_config.id,
1690 &ffhh::Resolution::Duration(resolution_nanos),
1691 useful_ticks,
1692 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible"),
1693 )
1694 };
1695
1696 let hrtimer_scheduled_if_error =
1697 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1698 let hrtimer_task = scope.spawn_local(async move {
1699 debug!("hrtimer_task: waiting for hrtimer driver response");
1700 trace::instant!("alarms", "hrtimer:started", trace::Scope::Process);
1701 let response = start_and_wait_fut.await;
1702 trace::instant!("alarms", "hrtimer:response", trace::Scope::Process);
1703 match response {
1704 Err(TimerOpsError::Fidl(e)) => {
1705 defer! {
1706 signal(&hrtimer_scheduled_if_error);
1708 }
1709 trace::instant!("alarms", "hrtimer:response:fidl_error", trace::Scope::Process);
1710 command_send
1711 .start_send(Cmd::AlarmFidlError { expired_deadline: now, error: e })
1712 .unwrap();
1713 }
1715 Err(TimerOpsError::Driver(e)) => {
1716 defer! {
1717 signal(&hrtimer_scheduled_if_error);
1720 }
1721 let driver_error_str = format!("{:?}", e);
1722 trace::instant!("alarms", "hrtimer:response:driver_error", trace::Scope::Process, "error" => &driver_error_str[..]);
1723 debug!("schedule_hrtimer: hrtimer driver error: {:?}", e);
1726 command_send
1727 .start_send(Cmd::AlarmDriverError {
1728 expired_deadline: now,
1729 error: e,
1730 timer_config_id,
1731 resolution_nanos,
1732 ticks: useful_ticks,
1733 })
1734 .unwrap();
1735 }
1737 Ok(keep_alive) => {
1738 trace::instant!("alarms", "hrtimer:response:alarm", trace::Scope::Process);
1739 debug!("hrtimer: got alarm response: {:?}", keep_alive);
1740 command_send
1742 .start_send(Cmd::Alarm { expired_deadline: deadline, keep_alive })
1743 .unwrap();
1744 }
1745 }
1746 debug!("hrtimer_task: exiting task.");
1747 trace::instant!("alarms", "hrtimer:task_exit", trace::Scope::Process);
1748 }).into();
1749 debug!("schedule_hrtimer: waiting for event to be signaled");
1750
1751 {
1752 let _i = ScopedInc::new(&wait_signaled_count);
1753 log_long_op!(wait_signaled(&hrtimer_scheduled));
1755 }
1756
1757 let now_after_signaled = fasync::BootInstant::now();
1758 let duration_until_scheduled: zx::BootDuration = (now_after_signaled - now).into();
1759 if duration_until_scheduled > zx::BootDuration::from_nanos(LONG_DELAY_NANOS) {
1760 trace::duration!("alarms", "schedule_hrtimer:unusual_duration",
1761 "duration" => duration_until_scheduled.into_nanos());
1762 warn!(
1763 "unusual duration until hrtimer scheduled: {}",
1764 format_duration(duration_until_scheduled)
1765 );
1766 }
1767 debug!("schedule_hrtimer: hrtimer wake alarm has been scheduled.");
1770 TimerState { task: hrtimer_task, deadline }
1771}
1772
1773fn notify_all(
1784 timers: &mut timers::Heap,
1785 lease_prototype: &zx::EventPair,
1786 reference_instant: fasync::BootInstant,
1787 timer_ops_error: Option<TimerOpsError>,
1788 _unusual_slack_histogram: &finspect::IntExponentialHistogramProperty,
1789) -> Result<usize> {
1790 trace::duration!("alarms", "notify_all");
1791 let now = fasync::BootInstant::now();
1792 let mut expired = 0;
1793 while let Some(timer_node) = timers.maybe_expire_earliest(reference_instant) {
1794 expired += 1;
1795 let deadline = timer_node.get_boot_deadline();
1797 let alarm = timer_node.id().alarm();
1798 let alarm_id = alarm.to_string();
1799 trace::duration!("alarms", "notify_all:notified", "alarm_id" => &*alarm_id);
1800 fuchsia_trace::flow_step!("alarms", "hrtimer_lifecycle", timers::get_trace_id(&alarm_id));
1801 let conn_id = timer_node.id().conn.clone();
1802 let slack: zx::BootDuration = deadline - now;
1803 if slack < zx::BootDuration::from_nanos(-LONG_DELAY_NANOS) {
1804 trace::duration!("alarms", "schedule_hrtimer:unusual_slack", "slack" => slack.into_nanos());
1805 warn!(
1807 "alarm id: {} had an unusually large slack: {}",
1808 alarm_id,
1809 format_duration(slack)
1810 );
1811 }
1812 if slack < zx::BootDuration::ZERO {
1813 }
1816 if let Some(ref err) = timer_ops_error {
1817 if !err.is_canceled() {
1820 timer_node.get_responder().send(alarm, Err(err.clone().into()));
1821 continue;
1822 }
1823 }
1824 debug!(
1825 concat!(
1826 "wake_alarm_loop: ALARM alarm_id: \"{}\"\n\tdeadline: {},\n\tconn_id: {:?},\n\t",
1827 "reference_instant: {},\n\tnow: {},\n\tslack: {}",
1828 ),
1829 alarm_id,
1830 format_timer(deadline.into()),
1831 conn_id,
1832 format_timer(reference_instant.into()),
1833 format_timer(now.into()),
1834 format_duration(slack),
1835 );
1836 let lease = lease_prototype.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1837 trace::instant!("alarms", "notify", trace::Scope::Process, "alarm_id" => &alarm_id[..], "conn_id" => conn_id);
1838 if let Some(Err(e)) = timer_node.get_responder().send(alarm, Ok(lease)) {
1839 error!("could not signal responder: {:?}", e);
1840 }
1841 trace::instant!("alarms", "notified", trace::Scope::Process);
1842 }
1843 trace::instant!("alarms", "notify", trace::Scope::Process, "expired_count" => expired);
1844 debug!("notify_all: expired count: {}", expired);
1845 Ok(expired)
1846 }
1848
1849pub async fn connect_to_hrtimer_async() -> Result<ffhh::DeviceProxy> {
1858 debug!("connect_to_hrtimer: trying service");
1859 let service = Service::open(ffhh::ServiceMarker).context("failed to open hrtimer service")?;
1860 let instance = service.watch_for_any().await.context("no hrtimer devices found")?;
1861 instance.connect_to_device().context("failed to connect to hrtimer device")
1862}
1863
1864#[cfg(test)]
1865mod tests {
1866 use super::*;
1867 use assert_matches::assert_matches;
1868 use diagnostics_assertions::{AnyProperty, assert_data_tree};
1869 use fuchsia_async::TestExecutor;
1870 use futures::select;
1871 use std::pin::pin;
1872 use test_case::test_case;
1873 use test_util::{assert_gt, assert_lt};
1874
1875 fn fake_wake_lease() -> fidl_fuchsia_power_system::LeaseToken {
1876 let (_lease, peer) = zx::EventPair::create();
1877 peer
1878 }
1879
1880 #[test]
1881 fn timer_duration_no_overflow() {
1882 let duration1 = TimerDuration {
1883 resolution: zx::BootDuration::from_seconds(100_000_000),
1884 ticks: u64::MAX,
1885 };
1886 let duration2 = TimerDuration {
1887 resolution: zx::BootDuration::from_seconds(110_000_000),
1888 ticks: u64::MAX,
1889 };
1890 assert_eq!(duration1, duration1);
1891 assert_eq!(duration2, duration2);
1892
1893 assert_lt!(duration1, duration2);
1894 assert_gt!(duration2, duration1);
1895 }
1896
1897 #[test_case(
1898 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1899 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1900 )]
1901 #[test_case(
1902 TimerDuration::new(zx::BootDuration::from_nanos(1), 10),
1903 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1904 )]
1905 #[test_case(
1906 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1907 TimerDuration::new(zx::BootDuration::from_nanos(1), 10)
1908 )]
1909 #[test_case(
1910 TimerDuration::new(zx::BootDuration::from_micros(1), 1),
1911 TimerDuration::new(zx::BootDuration::from_nanos(1), 1000)
1912 )]
1913 fn test_slack_eq(one: TimerDuration, other: TimerDuration) {
1914 assert_eq!(one, other);
1915 }
1916
1917 #[test_case(
1918 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1919 TimerDuration::new(zx::BootDuration::from_nanos(1), 2)
1920 )]
1921 #[test_case(
1922 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1923 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1924 )]
1925 fn test_slack_lt(one: TimerDuration, other: TimerDuration) {
1926 assert_lt!(one, other);
1927 }
1928
1929 #[test_case(
1930 TimerDuration::new(zx::BootDuration::from_nanos(1), 2),
1931 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1932 )]
1933 #[test_case(
1934 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1935 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1936 )]
1937 fn test_slack_gt(one: TimerDuration, other: TimerDuration) {
1938 assert_gt!(one, other);
1939 }
1940
1941 #[test_case(
1942 vec![zx::BootDuration::from_nanos(1)],
1943 100,
1944 zx::BootDuration::from_nanos(0),
1945 TimerDuration::new(zx::BootDuration::from_nanos(1), 1) ; "0ns becomes 1ns"
1946 )]
1947 #[test_case(
1948 vec![zx::BootDuration::from_nanos(1)],
1949 100,
1950 zx::BootDuration::from_nanos(50),
1951 TimerDuration::new(zx::BootDuration::from_nanos(1), 50) ; "Exact at 50x1ns"
1952 )]
1953 #[test_case(
1954 vec![zx::BootDuration::from_nanos(2)],
1955 100,
1956 zx::BootDuration::from_nanos(50),
1957 TimerDuration::new(zx::BootDuration::from_nanos(2), 25) ; "Exact at 25x2ns"
1958 )]
1959 #[test_case(
1960 vec![zx::BootDuration::from_nanos(3)],
1961 100,
1962 zx::BootDuration::from_nanos(50),
1963 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "Inexact at 51ns"
1965 )]
1966 #[test_case(
1967 vec![
1968 zx::BootDuration::from_nanos(3),
1969 zx::BootDuration::from_nanos(4)
1970 ],
1971 100,
1972 zx::BootDuration::from_nanos(50),
1973 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "3ns is a better resolution"
1974 )]
1975 #[test_case(
1976 vec![
1977 zx::BootDuration::from_nanos(1000),
1978 ],
1979 100,
1980 zx::BootDuration::from_nanos(50),
1981 TimerDuration::new(zx::BootDuration::from_nanos(1000), 1) ;
1982 "950ns negative slack is the best we can do"
1983 )]
1984 #[test_case(
1985 vec![
1986 zx::BootDuration::from_nanos(1),
1987 ],
1988 10,
1989 zx::BootDuration::from_nanos(50),
1990 TimerDuration::new(zx::BootDuration::from_nanos(1), 10) ;
1991 "10ns positive slack is the best we can do"
1992 )]
1993 #[test_case(
1994 vec![
1995 zx::BootDuration::from_millis(1),
1996 zx::BootDuration::from_micros(100),
1997 zx::BootDuration::from_micros(10),
1998 zx::BootDuration::from_micros(1),
1999 ],
2000 20, zx::BootDuration::from_micros(150),
2002 TimerDuration::new(zx::BootDuration::from_micros(10), 15) ;
2003 "Realistic case with resolutions from driver, should be 15us"
2004 )]
2005 #[test_case(
2006 vec![
2007 zx::BootDuration::from_millis(1),
2008 zx::BootDuration::from_micros(100),
2009 zx::BootDuration::from_micros(10),
2010 zx::BootDuration::from_micros(1),
2011 ],
2012 2000, zx::BootDuration::from_micros(6000),
2014 TimerDuration::new(zx::BootDuration::from_millis(1), 6) ;
2015 "Coarser exact unit wins"
2016 )]
2017 #[test_case(
2018 vec![
2019 zx::BootDuration::from_millis(1),
2020 zx::BootDuration::from_millis(10),
2021 zx::BootDuration::from_millis(100),
2022 ],
2023 1000,
2024 zx::BootDuration::from_micros(-10),
2025 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
2026 "Negative duration gets the smallest timer duration"
2027 )]
2028 #[test_case(
2029 vec![
2030 zx::BootDuration::from_millis(1),
2031 zx::BootDuration::from_millis(10),
2032 zx::BootDuration::from_millis(100),
2033 ],
2034 1000,
2035 zx::BootDuration::ZERO,
2036 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
2037 "Zero duration gets the smallest timer duration"
2038 )]
2039 #[test_case(
2040 vec![zx::BootDuration::from_nanos(3)],
2041 100,
2042 zx::BootDuration::from_nanos(49),
2043 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ;
2044 "Single resolution picks q+1 even when p_slack < n_slack"
2045 )]
2046 #[test_case(
2047 vec![zx::BootDuration::from_seconds(1)],
2048 1000,
2049 zx::BootDuration::from_millis(20_350),
2050 TimerDuration::new(zx::BootDuration::from_seconds(1), 21) ;
2051 "Single 1s coarse resolution with multi-second duration picks 21s"
2052 )]
2053 #[test_case(
2054 vec![zx::BootDuration::from_seconds(1)],
2055 1000,
2056 zx::BootDuration::from_millis(1_100),
2057 TimerDuration::new(zx::BootDuration::from_seconds(1), 2) ;
2058 "Single 1s coarse resolution picks 2s instead of early 1s wake"
2059 )]
2060 #[test_case(
2061 vec![zx::BootDuration::from_seconds(1)],
2062 60,
2063 zx::BootDuration::from_millis(100_200),
2064 TimerDuration::new(zx::BootDuration::from_seconds(1), 60) ;
2065 "Single 1s coarse resolution exceeding max_ticks clamps to max_ticks"
2066 )]
2067 #[test_case(
2068 vec![
2069 zx::BootDuration::from_millis(10),
2070 zx::BootDuration::from_seconds(1),
2071 ],
2072 20,
2073 zx::BootDuration::from_millis(5_150),
2074 TimerDuration::new(zx::BootDuration::from_seconds(1), 5) ;
2075 "Multi-resolution picks positive slack when finer resolution exists and p_slack < n_slack"
2076 )]
2077 #[test_case(
2078 vec![
2079 zx::BootDuration::from_seconds(1),
2080 zx::BootDuration::from_millis(10),
2081 ],
2082 20,
2083 zx::BootDuration::from_millis(5_150),
2084 TimerDuration::new(zx::BootDuration::from_seconds(1), 5) ;
2085 "Multi-resolution coarsest-first picks positive slack when finer resolution exists"
2086 )]
2087 #[test_case(
2088 vec![
2089 zx::BootDuration::from_millis(10),
2090 zx::BootDuration::from_seconds(1),
2091 ],
2092 20,
2093 zx::BootDuration::from_millis(5_850),
2094 TimerDuration::new(zx::BootDuration::from_seconds(1), 6) ;
2095 "Multi-resolution picks negative slack when n_slack < p_slack"
2096 )]
2097 #[test_case(
2098 vec![
2099 zx::BootDuration::from_millis(10),
2100 zx::BootDuration::from_seconds(1),
2101 ],
2102 20,
2103 zx::BootDuration::from_millis(152),
2104 TimerDuration::new(zx::BootDuration::from_millis(10), 16) ;
2105 "Multi-resolution already at finest resolution picks negative slack"
2106 )]
2107 #[test_case(
2108 vec![
2109 zx::BootDuration::from_micros(10),
2110 zx::BootDuration::from_seconds(1),
2111 ],
2112 65535,
2113 zx::BootDuration::from_millis(700),
2114 TimerDuration::new(zx::BootDuration::from_micros(10), 65535) ;
2115 "Finest resolution clamped to max_ticks is preferred over coarse overshoot"
2116 )]
2117 #[test_case(
2118 vec![
2119 zx::BootDuration::from_millis(1),
2120 zx::BootDuration::from_seconds(10),
2121 ],
2122 1000,
2123 zx::BootDuration::from_seconds(5),
2124 TimerDuration::new(zx::BootDuration::from_millis(1), 1000) ;
2125 "Clamped finest resolution beats coarse single-tick overshoot"
2126 )]
2127 #[test_case(
2128 vec![
2129 zx::BootDuration::from_millis(1),
2130 zx::BootDuration::from_seconds(1),
2131 ],
2132 100,
2133 zx::BootDuration::from_millis(150),
2134 TimerDuration::new(zx::BootDuration::from_millis(1), 100) ;
2135 "Remainder exceeding finest max_ticks reprograms at finest resolution"
2136 )]
2137 fn test_pick_setting(
2138 resolutions: Vec<zx::BootDuration>,
2139 max_ticks: u64,
2140 duration: zx::BootDuration,
2141 expected: TimerDuration,
2142 ) {
2143 let config = TimerConfig::new_from_data(MAIN_TIMER_ID as u64, &resolutions[..], max_ticks);
2144 let actual = config.pick_setting(duration);
2145
2146 assert_slack_eq(expected, actual);
2149 }
2150
2151 fn assert_slack_eq(expected: TimerDuration, actual: TimerDuration) {
2153 let slack = expected.duration() - actual.duration();
2154 assert_eq!(
2155 actual.resolution(),
2156 expected.resolution(),
2157 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2158 expected,
2159 format_duration(expected.duration()),
2160 actual,
2161 format_duration(actual.duration()),
2162 format_duration(slack)
2163 );
2164 assert_eq!(
2165 actual.ticks(),
2166 expected.ticks(),
2167 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2168 expected,
2169 format_duration(expected.duration()),
2170 actual,
2171 format_duration(actual.duration()),
2172 format_duration(slack)
2173 );
2174 }
2175
2176 #[derive(Debug)]
2177 enum FakeCmd {
2178 SetProperties {
2179 resolutions: Vec<zx::BootDuration>,
2180 max_ticks: i64,
2181 keep_alive: zx::EventPair,
2182 done: zx::Event,
2183 },
2184 SetScheduleDelay {
2185 delay: zx::BootDuration,
2186 done: zx::Event,
2187 },
2188 }
2189
2190 use std::cell::RefCell;
2191 use std::rc::Rc;
2192
2193 fn fake_hrtimer_connection(
2199 scope: fasync::ScopeHandle,
2200 rcv: mpsc::Receiver<FakeCmd>,
2201 ) -> (ffhh::DeviceProxy, Rc<RefCell<Vec<(i64, u64)>>>) {
2202 debug!("fake_hrtimer_connection: entry.");
2203 let (hrtimer, mut stream) =
2204 fidl::endpoints::create_proxy_and_stream::<ffhh::DeviceMarker>();
2205 let start_and_wait_calls = Rc::new(RefCell::new(Vec::new()));
2206 let recorded_calls = start_and_wait_calls.clone();
2207 scope.clone().spawn_local(async move {
2208 let mut rcv = rcv.fuse();
2209 let timer_properties = Rc::new(RefCell::new(None));
2210 let wake_lease = Rc::new(RefCell::new(None));
2211 let schedule_delay = Rc::new(RefCell::new(zx::BootDuration::ZERO));
2212 let running_task: Rc<RefCell<Option<fasync::Task<()>>>> = Rc::new(RefCell::new(None));
2213
2214 let timer_running = Rc::new(RefCell::new(false));
2218
2219 loop {
2220 let timer_properties = timer_properties.clone();
2221 let wake_lease = wake_lease.clone();
2222 select! {
2223 cmd = rcv.next() => {
2224 debug!("fake_hrtimer_connection: cmd: {:?}", cmd);
2225 match cmd {
2226 Some(FakeCmd::SetProperties{ resolutions, max_ticks, keep_alive, done}) => {
2227 let mut timer_props = vec![];
2228 for v in 0..10 {
2229 timer_props.push(ffhh::TimerProperties {
2230 supported_resolutions: Some(
2231 resolutions.iter()
2232 .map(|d| ffhh::Resolution::Duration(d.into_nanos())).collect()),
2233 max_ticks: Some(max_ticks.try_into().unwrap()),
2234 supports_wait: Some(true),
2236 id: Some(v),
2237 ..Default::default()
2238 },
2239 );
2240 }
2241 *timer_properties.borrow_mut() = Some(timer_props);
2242 *wake_lease.borrow_mut() = Some(keep_alive);
2243 debug!("set timer properties to: {:?}", timer_properties);
2244 signal(&done);
2245 }
2246 Some(FakeCmd::SetScheduleDelay { delay, done }) => {
2247 *schedule_delay.borrow_mut() = delay;
2248 signal(&done);
2249 }
2250 e => {
2251 panic!("unrecognized command: {:?}", e);
2252 }
2253 }
2254 },
2256 event = stream.next() => {
2257 debug!("fake_hrtimer_connection: event: {:?}", event);
2258 if let Some(Ok(event)) = event {
2259 match event {
2260 ffhh::DeviceRequest::Start { responder, .. } => {
2261 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2262 *timer_running.borrow_mut() = true;
2263 responder.send(Ok(())).expect("");
2264 }
2265 ffhh::DeviceRequest::Stop { responder, .. } => {
2266 *timer_running.borrow_mut() = false;
2267 let _ = running_task.borrow_mut().take();
2268 responder.send(Ok(())).expect("");
2269 }
2270 ffhh::DeviceRequest::GetTicksLeft { responder, .. } => {
2271 responder.send(Ok(1)).expect("");
2272 }
2273 ffhh::DeviceRequest::SetEvent { responder, .. } => {
2274 responder.send(Ok(())).expect("");
2275 }
2276 ffhh::DeviceRequest::StartAndWait { id, resolution, ticks, setup_event, responder, .. } => {
2277 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2278 *timer_running.borrow_mut() = true;
2279 debug!("fake_hrtimer_connection: starting timer: \"{}\", resolution: {:?}, ticks: {}", id, resolution, ticks);
2280 let resolution_nanos = match resolution {
2281 ffhh::Resolution::Duration(e) => e,
2282 _ => {
2283 error!("resolution has an unexpected value");
2284 1
2285 }
2286 };
2287 recorded_calls.borrow_mut().push((resolution_nanos, ticks));
2288 let ticks: i64 = ticks.try_into().unwrap();
2289 let sleep_duration =
2290 zx::BootDuration::from_nanos(ticks * resolution_nanos);
2291 let delay = *schedule_delay.borrow();
2292 let timer_running_clone = timer_running.clone();
2293 struct ResponderGuard(Option<ffhh::DeviceStartAndWaitResponder>);
2294 impl Drop for ResponderGuard {
2295 fn drop(&mut self) {
2296 if let Some(r) = self.0.take() {
2297 let _ = r.send(Err(ffhh::DriverError::Canceled));
2298 }
2299 }
2300 }
2301 let mut responder_guard = ResponderGuard(Some(responder));
2302 let task = fasync::Task::local(async move {
2303 if delay > zx::BootDuration::ZERO {
2304 fasync::Timer::new(delay).await;
2305 }
2306 signal(&setup_event);
2309
2310 fasync::Timer::new(sleep_duration).await;
2313 *timer_running_clone.borrow_mut() = false;
2314 responder_guard
2315 .0
2316 .take()
2317 .unwrap()
2318 .send(Ok(wake_lease
2319 .borrow()
2320 .as_ref()
2321 .unwrap()
2322 .duplicate_handle(zx::Rights::SAME_RIGHTS)
2323 .unwrap()))
2324 .unwrap();
2325 debug!("StartAndWait: hrtimer expired");
2326 });
2327 *running_task.borrow_mut() = Some(task);
2328 }
2329 ffhh::DeviceRequest::StartAndWait2 { responder, .. } => {
2330 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2331 *timer_running.borrow_mut() = true;
2332 responder.send(Err(ffhh::DriverError::InternalError)).expect("");
2333 }
2334 ffhh::DeviceRequest::GetProperties { responder, .. } => {
2335 if (*timer_properties).borrow().is_none() {
2336 error!("timer_properties is empty, this is not what you want!");
2337 }
2338 responder
2339 .send(ffhh::Properties {
2340 timers_properties: (*timer_properties).borrow().clone(),
2341 ..Default::default()
2342 })
2343 .expect("");
2344 }
2345 ffhh::DeviceRequest::ReadTimer { responder, .. } => {
2346 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2347 }
2348 ffhh::DeviceRequest::ReadClock { responder, .. } => {
2349 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2350 }
2351 ffhh::DeviceRequest::_UnknownMethod { .. } => todo!(),
2352 }
2353 }
2354 },
2355 }
2356 }
2357 });
2358 (hrtimer, start_and_wait_calls)
2359 }
2360
2361 fn clone_utc_clock(orig: &fxr::UtcClock) -> fxr::UtcClock {
2362 orig.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2363 }
2364
2365 struct TestContext {
2366 wake_proxy: fta::WakeAlarmsProxy,
2367 _scope: fasync::Scope,
2368 _cmd_tx: mpsc::Sender<FakeCmd>,
2369 utc_clock: fxr::UtcClock,
2371 utc_backstop: fxr::UtcInstant,
2372 }
2373
2374 impl TestContext {
2375 async fn new() -> Self {
2376 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(0)).await;
2377
2378 let scope = fasync::Scope::new();
2379 let utc_backstop = fxr::UtcInstant::from_nanos(1000);
2380 let utc_clock =
2381 fxr::UtcClock::create(zx::ClockOpts::empty(), Some(utc_backstop)).unwrap();
2382 let utc_clone = clone_utc_clock(&utc_clock);
2383 let (mut cmd_tx, wake_proxy) = {
2384 let (tx, rx) = mpsc::channel::<FakeCmd>(0);
2385 let (hrtimer_proxy, _scheduled_calls) =
2386 fake_hrtimer_connection(scope.to_handle(), rx);
2387
2388 let inspector = finspect::component::inspector();
2389 let alarms = Rc::new(Loop::new(
2390 scope.to_handle(),
2391 hrtimer_proxy,
2392 inspector.root().create_child("test"),
2393 utc_clone,
2394 ));
2395
2396 let (proxy, stream) =
2397 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2398 scope.spawn_local(async move {
2399 serve(alarms, stream).await;
2400 });
2401 (tx, proxy)
2402 };
2403
2404 let (_wake_lease, peer) = zx::EventPair::create();
2405 let done = zx::Event::create();
2406 cmd_tx
2407 .start_send(FakeCmd::SetProperties {
2408 resolutions: vec![zx::Duration::from_nanos(1)],
2409 max_ticks: 100,
2410 keep_alive: peer,
2411 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2412 })
2413 .unwrap();
2414
2415 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
2417
2418 Self { wake_proxy, _scope: scope, _cmd_tx: cmd_tx, utc_clock, utc_backstop }
2419 }
2420 }
2421
2422 impl Drop for TestContext {
2423 fn drop(&mut self) {
2424 assert_matches!(TestExecutor::next_timer(), None, "Unexpected lingering timers");
2425 }
2426 }
2427
2428 #[fuchsia::test(allow_stalls = false)]
2429 async fn test_basic_timed_wait() {
2430 let ctx = TestContext::new().await;
2431
2432 let deadline = zx::BootInstant::from_nanos(100);
2433 let setup_done = zx::Event::create();
2434 let mut set_task = ctx.wake_proxy.set_and_wait(
2435 deadline.into(),
2436 fta::SetMode::NotifySetupDone(
2437 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2438 ),
2439 "Hello".into(),
2440 );
2441
2442 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
2443
2444 let mut setup_done_task =
2445 pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2446 assert_matches!(
2447 TestExecutor::poll_until_stalled(&mut setup_done_task).await,
2448 Poll::Ready(Ok(_)),
2449 "Setup event not triggered after scheduling an alarm"
2450 );
2451
2452 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(100)).await;
2453 assert_matches!(TestExecutor::poll_until_stalled(set_task).await, Poll::Ready(Ok(Ok(_))));
2454 }
2455
2456 #[fuchsia::test(allow_stalls = false)]
2457 async fn test_basic_timed_wait_notify() {
2458 const ALARM_ID: &str = "Hello";
2459 let ctx = TestContext::new().await;
2460
2461 let (notifier_client, mut notifier_stream) =
2462 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2463 let setup_done = zx::Event::create();
2464 assert_matches!(
2465 ctx.wake_proxy
2466 .set(
2467 notifier_client,
2468 fidl::BootInstant::from_nanos(2),
2469 fta::SetMode::NotifySetupDone(
2470 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2471 ),
2472 ALARM_ID,
2473 )
2474 .await,
2475 Ok(Ok(()))
2476 );
2477
2478 let mut done_task = pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2479 assert_matches!(
2480 TestExecutor::poll_until_stalled(&mut done_task).await,
2481 Poll::Ready(Ok(_)),
2482 "Setup event not triggered after scheduling an alarm"
2483 );
2484
2485 let mut next_task = notifier_stream.next();
2486 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2487
2488 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2489 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2490
2491 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(2)).await;
2492 assert_matches!(
2493 TestExecutor::poll_until_stalled(next_task).await,
2494 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2495 );
2496 }
2497
2498 #[fuchsia::test(allow_stalls = false)]
2499 async fn test_two_alarms_same() {
2500 const DEADLINE_NANOS: i64 = 100;
2501
2502 let ctx = TestContext::new().await;
2503
2504 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2505 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2506 fta::SetMode::KeepAlive(fake_wake_lease()),
2507 "Hello1".into(),
2508 );
2509 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2510 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2511 fta::SetMode::KeepAlive(fake_wake_lease()),
2512 "Hello2".into(),
2513 );
2514
2515 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2516 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2517
2518 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2519
2520 assert_matches!(
2521 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2522 Poll::Ready(Ok(Ok(_)))
2523 );
2524 assert_matches!(
2525 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2526 Poll::Ready(Ok(Ok(_)))
2527 );
2528 }
2529
2530 #[fuchsia::test(allow_stalls = false)]
2531 async fn test_two_alarms_same_notify() {
2532 const DEADLINE_NANOS: i64 = 100;
2533 const ALARM_ID_1: &str = "Hello1";
2534 const ALARM_ID_2: &str = "Hello2";
2535
2536 let ctx = TestContext::new().await;
2537
2538 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2539 let (notifier_client, notifier_stream) =
2540 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2541 assert_matches!(
2542 ctx.wake_proxy
2543 .set(
2544 notifier_client,
2545 fidl::BootInstant::from_nanos(deadline_nanos),
2546 fta::SetMode::KeepAlive(fake_wake_lease()),
2547 alarm_id,
2548 )
2549 .await,
2550 Ok(Ok(()))
2551 );
2552 notifier_stream
2553 };
2554
2555 let mut notifier_1 = schedule(DEADLINE_NANOS, ALARM_ID_1).await;
2556 let mut notifier_2 = schedule(DEADLINE_NANOS, ALARM_ID_2).await;
2557
2558 let mut next_task_1 = notifier_1.next();
2559 let mut next_task_2 = notifier_2.next();
2560
2561 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2562 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2563
2564 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2565
2566 assert_matches!(
2567 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2568 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_1
2569 );
2570 assert_matches!(
2571 TestExecutor::poll_until_stalled(&mut next_task_2).await,
2572 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_2
2573 );
2574
2575 assert_matches!(
2576 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2577 Poll::Ready(None)
2578 );
2579 assert_matches!(
2580 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2581 Poll::Ready(None)
2582 );
2583 }
2584
2585 #[test_case(100, 200 ; "push out")]
2586 #[test_case(200, 100 ; "pull in")]
2587 #[fuchsia::test(allow_stalls = false)]
2588 async fn test_two_alarms_different(
2589 first_deadline_nanos: i64,
2591 second_deadline_nanos: i64,
2593 ) {
2594 let ctx = TestContext::new().await;
2595
2596 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2597 fidl::BootInstant::from_nanos(first_deadline_nanos),
2598 fta::SetMode::KeepAlive(fake_wake_lease()),
2599 "Hello1".into(),
2600 );
2601 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2602 fidl::BootInstant::from_nanos(second_deadline_nanos),
2603 fta::SetMode::KeepAlive(fake_wake_lease()),
2604 "Hello2".into(),
2605 );
2606
2607 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2608 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2609
2610 let mut tasks = [(first_deadline_nanos, set_task_1), (second_deadline_nanos, set_task_2)];
2612 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2613 let [mut first_task, mut second_task] = tasks;
2614
2615 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(first_task.0)).await;
2617 assert_matches!(
2618 TestExecutor::poll_until_stalled(&mut first_task.1).await,
2619 Poll::Ready(Ok(Ok(_)))
2620 );
2621 assert_matches!(TestExecutor::poll_until_stalled(&mut second_task.1).await, Poll::Pending);
2622
2623 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(second_task.0)).await;
2624 assert_matches!(
2625 TestExecutor::poll_until_stalled(&mut second_task.1).await,
2626 Poll::Ready(Ok(Ok(_)))
2627 );
2628 }
2629
2630 #[test_case(100, 200 ; "push out")]
2631 #[test_case(200, 100 ; "pull in")]
2632 #[fuchsia::test(allow_stalls = false)]
2633 async fn test_two_alarms_different_notify(
2634 first_deadline_nanos: i64,
2636 second_deadline_nanos: i64,
2638 ) {
2639 const ALARM_ID_1: &str = "Hello1";
2640 const ALARM_ID_2: &str = "Hello2";
2641
2642 let ctx = TestContext::new().await;
2643
2644 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2645 let (notifier_client, notifier_stream) =
2646 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2647 assert_matches!(
2648 ctx.wake_proxy
2649 .set(
2650 notifier_client,
2651 fidl::BootInstant::from_nanos(deadline_nanos),
2652 fta::SetMode::KeepAlive(fake_wake_lease()),
2653 alarm_id,
2654 )
2655 .await,
2656 Ok(Ok(()))
2657 );
2658 notifier_stream
2659 };
2660
2661 let mut notifier_all = futures::stream::select_all([
2663 schedule(first_deadline_nanos, ALARM_ID_1).await,
2664 schedule(second_deadline_nanos, ALARM_ID_2).await,
2665 ]);
2666 let [(early_ns, early_alarm), (later_ns, later_alarm)] = {
2667 let mut tasks =
2668 [(first_deadline_nanos, ALARM_ID_1), (second_deadline_nanos, ALARM_ID_2)];
2669 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2670 tasks
2671 };
2672
2673 let mut next_task = notifier_all.next();
2675 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2676
2677 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(early_ns)).await;
2678 assert_matches!(
2679 TestExecutor::poll_until_stalled(next_task).await,
2680 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == early_alarm
2681 );
2682
2683 let mut next_task = notifier_all.next();
2684 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2685
2686 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(later_ns)).await;
2687 assert_matches!(
2688 TestExecutor::poll_until_stalled(next_task).await,
2689 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == later_alarm
2690 );
2691 assert_matches!(
2692 TestExecutor::poll_until_stalled(notifier_all.next()).await,
2693 Poll::Ready(None)
2694 );
2695 }
2696
2697 #[fuchsia::test(allow_stalls = false)]
2698 async fn test_alarm_immediate() {
2699 let ctx = TestContext::new().await;
2700 let mut set_task = ctx.wake_proxy.set_and_wait(
2701 fidl::BootInstant::INFINITE_PAST,
2702 fta::SetMode::KeepAlive(fake_wake_lease()),
2703 "Hello1".into(),
2704 );
2705 assert_matches!(
2706 TestExecutor::poll_until_stalled(&mut set_task).await,
2707 Poll::Ready(Ok(Ok(_)))
2708 );
2709 }
2710
2711 #[fuchsia::test(allow_stalls = false)]
2712 async fn test_alarm_immediate_notify() {
2713 const ALARM_ID: &str = "Hello";
2714 let ctx = TestContext::new().await;
2715
2716 let (notifier_client, mut notifier_stream) =
2717 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2718
2719 let mut set_task = ctx.wake_proxy.set(
2720 notifier_client,
2721 fidl::BootInstant::INFINITE_PAST,
2722 fta::SetMode::KeepAlive(fake_wake_lease()),
2723 ALARM_ID,
2724 );
2725 assert_matches!(
2726 TestExecutor::poll_until_stalled(&mut set_task).await,
2727 Poll::Ready(Ok(Ok(_)))
2728 );
2729 assert_matches!(
2730 TestExecutor::poll_until_stalled(notifier_stream.next()).await,
2731 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2732 );
2733 }
2734
2735 #[test_case(200, 100 ; "pull in")]
2738 #[test_case(100, 200 ; "push out")]
2739 #[test_case(100, 100 ; "replace with the same deadline")]
2740 #[fuchsia::test(allow_stalls = false)]
2741 async fn test_reschedule(initial_deadline_nanos: i64, override_deadline_nanos: i64) {
2742 const ALARM_ID: &str = "Hello";
2743
2744 let ctx = TestContext::new().await;
2745
2746 let schedule = |deadline_nanos: i64| {
2747 let setup_done = zx::Event::create();
2748 let task = ctx.wake_proxy.set_and_wait(
2749 fidl::BootInstant::from_nanos(deadline_nanos),
2750 fta::SetMode::NotifySetupDone(
2751 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2752 ),
2753 ALARM_ID.into(),
2754 );
2755 (task, setup_done)
2756 };
2757
2758 let (mut set_task_1, setup_done_1) = schedule(initial_deadline_nanos);
2761 fasync::OnSignals::new(setup_done_1, zx::Signals::EVENT_SIGNALED).await.unwrap();
2762 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2763
2764 let (mut set_task_2, setup_done_2) = schedule(override_deadline_nanos);
2767 fasync::OnSignals::new(setup_done_2, zx::Signals::EVENT_SIGNALED).await.unwrap();
2768 assert_matches!(
2769 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2770 Poll::Ready(Ok(Err(fta::WakeAlarmsError::Dropped)))
2771 );
2772 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2773
2774 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos - 1))
2776 .await;
2777 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2778 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos))
2779 .await;
2780 assert_matches!(
2781 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2782 Poll::Ready(Ok(Ok(_)))
2783 );
2784
2785 assert_data_tree!(finspect::component::inspector(), root: {
2788 test: {
2789 hardware: {
2790 current_deadline: "(none)",
2792 remaining_until_alarm: "(none)",
2793 },
2794 now_formatted: format!("{override_deadline_nanos}ns ({override_deadline_nanos})"),
2795 now_ns: override_deadline_nanos,
2796 pending_timers: "Boot:\n\t\n\tUTC:\n\t",
2797 pending_timers_count: 0u64,
2798 requested_deadlines_ns: AnyProperty,
2799 schedule_delay_ns: AnyProperty,
2800 slack_ns: AnyProperty,
2801 boot_deadlines_count: AnyProperty,
2802 utc_deadlines_count: AnyProperty,
2803 debug_node: contains {},
2804 },
2805 });
2806 }
2807
2808 #[fuchsia::test(allow_stalls = false)]
2811 async fn test_reschedule_notify() {
2812 const ALARM_ID: &str = "Hello";
2813 const INITIAL_DEADLINE_NANOS: i64 = 100;
2814 const OVERRIDE_DEADLINE_NANOS: i64 = 200;
2815
2816 let ctx = TestContext::new().await;
2817
2818 let schedule = async |deadline_nanos: i64| {
2819 let (notifier_client, notifier_stream) =
2820 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2821 assert_matches!(
2822 ctx.wake_proxy
2823 .set(
2824 notifier_client,
2825 fidl::BootInstant::from_nanos(deadline_nanos),
2826 fta::SetMode::KeepAlive(fake_wake_lease()),
2827 ALARM_ID.into(),
2828 )
2829 .await,
2830 Ok(Ok(()))
2831 );
2832 notifier_stream
2833 };
2834
2835 let mut notifier_1 = schedule(INITIAL_DEADLINE_NANOS).await;
2836 let mut next_task_1 = notifier_1.next();
2837 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2838
2839 let mut notifier_2 = schedule(OVERRIDE_DEADLINE_NANOS).await;
2840 let mut next_task_2 = notifier_2.next();
2841 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2842
2843 assert_matches!(
2845 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2846 Poll::Ready(Some(Ok(fta::NotifierRequest::NotifyError { alarm_id, error, .. }))) if alarm_id == ALARM_ID && error == fta::WakeAlarmsError::Dropped
2847 );
2848 assert_matches!(
2849 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2850 Poll::Ready(None)
2851 );
2852
2853 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(OVERRIDE_DEADLINE_NANOS))
2855 .await;
2856 assert_matches!(
2857 TestExecutor::poll_until_stalled(next_task_2).await,
2858 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2859 );
2860 assert_matches!(
2861 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2862 Poll::Ready(None)
2863 );
2864 }
2865
2866 #[fuchsia::test(allow_stalls = false)]
2869 async fn test_fidl_error_on_reschedule() {
2870 const DEADLINE_NANOS: i64 = 100;
2871
2872 let (wake_proxy, _stream) =
2873 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2874 drop(_stream);
2875
2876 assert_matches!(
2877 wake_proxy
2878 .set_and_wait(
2879 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2880 fta::SetMode::KeepAlive(fake_wake_lease()),
2881 "hello1".into(),
2882 )
2883 .await,
2884 Err(fidl::Error::ClientChannelClosed { .. })
2885 );
2886
2887 assert_matches!(
2888 wake_proxy
2889 .set_and_wait(
2890 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2891 fta::SetMode::KeepAlive(fake_wake_lease()),
2892 "hello2".into(),
2893 )
2894 .await,
2895 Err(fidl::Error::ClientChannelClosed { .. })
2896 );
2897 }
2898
2899 #[fuchsia::test(allow_stalls = false)]
2902 async fn test_set_and_wait_utc() {
2903 const ALARM_ID: &str = "Hello_set_and_wait_utc";
2904 let ctx = TestContext::new().await;
2905
2906 let now_boot = fasync::BootInstant::now();
2907 ctx.utc_clock
2908 .update(
2909 zx::ClockUpdate::builder()
2910 .absolute_value(now_boot.into(), ctx.utc_backstop)
2911 .build(),
2912 )
2913 .unwrap();
2914
2915 let timestamp_utc = ctx.utc_backstop + fxr::UtcDuration::from_nanos(2);
2916 let mut wake_fut = ctx.wake_proxy.set_and_wait_utc(
2917 &fta::InstantUtc { timestamp_utc: timestamp_utc.into_nanos() },
2918 fta::SetMode::KeepAlive(fake_wake_lease()),
2919 ALARM_ID,
2920 );
2921
2922 assert_matches!(TestExecutor::poll_until_stalled(&mut wake_fut).await, Poll::Pending);
2924
2925 ctx.utc_clock
2927 .update(
2928 zx::ClockUpdate::builder()
2929 .absolute_value(
2930 now_boot.into(),
2931 ctx.utc_backstop + fxr::UtcDuration::from_nanos(100),
2932 )
2933 .build(),
2934 )
2935 .unwrap();
2936
2937 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2939 assert_matches!(TestExecutor::poll_until_stalled(wake_fut).await, Poll::Ready(_));
2940 }
2941
2942 #[fuchsia::test(allow_stalls = false)]
2946 async fn test_alarm_expired_post_schedule() {
2947 let mut ctx = TestContext::new().await;
2948
2949 let done = zx::Event::create();
2950 ctx._cmd_tx
2951 .start_send(FakeCmd::SetScheduleDelay {
2952 delay: zx::BootDuration::from_nanos(30),
2953 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2954 })
2955 .unwrap();
2956 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
2957
2958 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(80)).await;
2960
2961 let setup_done = zx::Event::create();
2962 let mut set_task = ctx.wake_proxy.set_and_wait(
2963 zx::BootInstant::from_nanos(100).into(),
2964 fta::SetMode::NotifySetupDone(
2965 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2966 ),
2967 "post_schedule_expired".into(),
2968 );
2969 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
2970
2971 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(110)).await;
2977
2978 let mut setup_done_task =
2979 pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2980 assert_matches!(
2981 TestExecutor::poll_until_stalled(&mut setup_done_task).await,
2982 Poll::Ready(Ok(_))
2983 );
2984 assert_matches!(
2985 TestExecutor::poll_until_stalled(&mut set_task).await,
2986 Poll::Ready(Ok(Ok(_)))
2987 );
2988 }
2989
2990 #[fuchsia::test(allow_stalls = false)]
2993 async fn test_alarm_expired_post_schedule_reschedules_next() {
2994 let mut ctx = TestContext::new().await;
2995
2996 let mut later_task = ctx.wake_proxy.set_and_wait(
2998 zx::BootInstant::from_nanos(200).into(),
2999 fta::SetMode::KeepAlive(fake_wake_lease()),
3000 "later_alarm".into(),
3001 );
3002 assert_matches!(TestExecutor::poll_until_stalled(&mut later_task).await, Poll::Pending);
3003
3004 let done = zx::Event::create();
3006 ctx._cmd_tx
3007 .start_send(FakeCmd::SetScheduleDelay {
3008 delay: zx::BootDuration::from_nanos(30),
3009 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
3010 })
3011 .unwrap();
3012 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
3013 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(80)).await;
3014
3015 let mut early_task = ctx.wake_proxy.set_and_wait(
3017 zx::BootInstant::from_nanos(100).into(),
3018 fta::SetMode::KeepAlive(fake_wake_lease()),
3019 "early_alarm".into(),
3020 );
3021 assert_matches!(TestExecutor::poll_until_stalled(&mut early_task).await, Poll::Pending);
3022
3023 let done = zx::Event::create();
3026 ctx._cmd_tx
3027 .start_send(FakeCmd::SetScheduleDelay {
3028 delay: zx::BootDuration::ZERO,
3029 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
3030 })
3031 .unwrap();
3032 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
3033
3034 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(110)).await;
3035 assert_matches!(
3036 TestExecutor::poll_until_stalled(&mut early_task).await,
3037 Poll::Ready(Ok(Ok(_)))
3038 );
3039 assert_matches!(TestExecutor::poll_until_stalled(&mut later_task).await, Poll::Pending);
3040
3041 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(200)).await;
3043 assert_matches!(
3044 TestExecutor::poll_until_stalled(&mut later_task).await,
3045 Poll::Ready(Ok(Ok(_)))
3046 );
3047 }
3048
3049 #[fuchsia::test(allow_stalls = false)]
3053 async fn test_cancel_alarms() {
3054 let ctx = TestContext::new().await;
3055
3056 let mut task_100 = ctx.wake_proxy.set_and_wait(
3057 zx::BootInstant::from_nanos(100).into(),
3058 fta::SetMode::KeepAlive(fake_wake_lease()),
3059 "alarm_100".into(),
3060 );
3061 let now_boot = fasync::BootInstant::now();
3064 ctx.utc_clock
3065 .update(
3066 zx::ClockUpdate::builder()
3067 .absolute_value(now_boot.into(), ctx.utc_backstop)
3068 .build(),
3069 )
3070 .unwrap();
3071 let mut task_150_utc = ctx.wake_proxy.set_and_wait_utc(
3072 &fta::InstantUtc {
3073 timestamp_utc: (ctx.utc_backstop + fxr::UtcDuration::from_nanos(150)).into_nanos(),
3074 },
3075 fta::SetMode::KeepAlive(fake_wake_lease()),
3076 "alarm_150_utc",
3077 );
3078 let mut task_200 = ctx.wake_proxy.set_and_wait(
3079 zx::BootInstant::from_nanos(200).into(),
3080 fta::SetMode::KeepAlive(fake_wake_lease()),
3081 "alarm_200".into(),
3082 );
3083
3084 assert_matches!(TestExecutor::poll_until_stalled(&mut task_100).await, Poll::Pending);
3085 assert_matches!(TestExecutor::poll_until_stalled(&mut task_150_utc).await, Poll::Pending);
3086 assert_matches!(TestExecutor::poll_until_stalled(&mut task_200).await, Poll::Pending);
3087
3088 ctx.wake_proxy.cancel("alarm_150_utc").unwrap();
3090 assert_matches!(
3091 TestExecutor::poll_until_stalled(&mut task_150_utc).await,
3092 Poll::Ready(Ok(Err(fta::WakeAlarmsError::Dropped)))
3093 );
3094 assert_matches!(TestExecutor::poll_until_stalled(&mut task_100).await, Poll::Pending);
3095
3096 ctx.wake_proxy.cancel("alarm_100").unwrap();
3098 assert_matches!(
3099 TestExecutor::poll_until_stalled(&mut task_100).await,
3100 Poll::Ready(Ok(Err(fta::WakeAlarmsError::Dropped)))
3101 );
3102 assert_matches!(TestExecutor::poll_until_stalled(&mut task_200).await, Poll::Pending);
3103
3104 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(200)).await;
3106 assert_matches!(
3107 TestExecutor::poll_until_stalled(&mut task_200).await,
3108 Poll::Ready(Ok(Ok(_)))
3109 );
3110 }
3111
3112 #[fuchsia::test(allow_stalls = false)]
3115 async fn test_single_resolution_coarse_timer_no_early_double_wake() {
3116 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(0)).await;
3117
3118 let scope = fasync::Scope::new();
3119 let utc_backstop = fxr::UtcInstant::from_nanos(1000);
3120 let utc_clock = fxr::UtcClock::create(zx::ClockOpts::empty(), Some(utc_backstop)).unwrap();
3121 let (mut cmd_tx, wake_proxy, scheduled_calls) = {
3122 let (tx, rx) = mpsc::channel::<FakeCmd>(0);
3123 let (hrtimer_proxy, scheduled_calls) = fake_hrtimer_connection(scope.to_handle(), rx);
3124
3125 let inspector = finspect::component::inspector();
3126 let alarms = Rc::new(Loop::new(
3127 scope.to_handle(),
3128 hrtimer_proxy,
3129 inspector.root().create_child("coarse_single_res_test"),
3130 clone_utc_clock(&utc_clock),
3131 ));
3132
3133 let (proxy, stream) =
3134 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
3135 scope.spawn_local(async move {
3136 serve(alarms, stream).await;
3137 });
3138 (tx, proxy, scheduled_calls)
3139 };
3140
3141 let (_wake_lease, peer) = zx::EventPair::create();
3142 let done = zx::Event::create();
3143 cmd_tx
3144 .start_send(FakeCmd::SetProperties {
3145 resolutions: vec![zx::BootDuration::from_seconds(1)],
3146 max_ticks: 1000,
3147 keep_alive: peer,
3148 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
3149 })
3150 .unwrap();
3151 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
3152
3153 let ctx =
3154 TestContext { wake_proxy, _scope: scope, _cmd_tx: cmd_tx, utc_clock, utc_backstop };
3155
3156 let deadline = zx::BootInstant::from_nanos(1_350_000_000);
3157 let setup_done = zx::Event::create();
3158 let mut set_task = ctx.wake_proxy.set_and_wait(
3159 deadline.into(),
3160 fta::SetMode::NotifySetupDone(
3161 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
3162 ),
3163 "coarse_alarm".into(),
3164 );
3165 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
3166
3167 let mut setup_done_task =
3168 pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
3169 assert_matches!(
3170 TestExecutor::poll_until_stalled(&mut setup_done_task).await,
3171 Poll::Ready(Ok(_))
3172 );
3173
3174 assert_eq!(*scheduled_calls.borrow(), vec![(1_000_000_000, 2)]);
3176 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1_000_000_000)).await;
3177 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
3178 assert_eq!(*scheduled_calls.borrow(), vec![(1_000_000_000, 2)]);
3179 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(2_000_000_000)).await;
3180 assert_matches!(
3181 TestExecutor::poll_until_stalled(&mut set_task).await,
3182 Poll::Ready(Ok(Ok(_)))
3183 );
3184 assert_eq!(*scheduled_calls.borrow(), vec![(1_000_000_000, 2)]);
3185 }
3186}