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