1mod emu;
29mod timers;
30
31use crate::emu::EmulationTimerOps;
32use anyhow::{Context, Result, anyhow};
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::connect_to_named_protocol_at_dir_root;
41use fuchsia_inspect as finspect;
42use fuchsia_inspect::{IntProperty, NumericProperty, Property};
43use fuchsia_runtime as fxr;
44use fuchsia_trace as trace;
45use futures::channel::mpsc;
46use futures::sink::SinkExt;
47use futures::{StreamExt, TryStreamExt};
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: no active timer to stop: {}", timer_id);
1335 }
1336 }
1337 Cmd::Alarm { expired_deadline, keep_alive } => {
1338 let _i = ScopedInc::new(&alarm_count);
1339
1340 trace::duration!("alarms", "Cmd::Alarm");
1341 debug!(
1346 "wake_timer_loop: ALARM!!! reached deadline: {}, wakey-wakey! {:?}",
1347 format_timer(expired_deadline.into()),
1348 keep_alive.koid().unwrap(),
1349 );
1350 let expired_count =
1351 notify_all(&mut timers, &keep_alive, now, None, &slack_histogram_prop)
1352 .expect("notification succeeds");
1353 if expired_count == 0 {
1354 debug!("wake_timer_loop: no expired alarms, reset hrtimer state");
1357 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1358 }
1359 hrtimer_status = match timers.peek_deadline_as_boot() {
1361 None => None,
1362 Some(deadline) => Some(
1363 schedule_hrtimer(
1364 scope.clone(),
1365 now,
1366 &timer_proxy,
1367 deadline,
1368 snd.clone(),
1369 &timer_config,
1370 &schedule_delay_prop,
1371 &hrtimer_node,
1372 )
1373 .await,
1374 ),
1375 }
1376 }
1377 Cmd::AlarmFidlError { expired_deadline, error } => {
1378 let _i = ScopedInc::new(&alarm_fidl_count);
1379
1380 trace::duration!("alarms", "Cmd::AlarmFidlError");
1381 let error_string = format!("{}", error);
1385 if !error_cache.contains_key(&error_string) {
1386 warn!(
1387 "wake_timer_loop: FIDL error: {}, deadline: {}, now: {}",
1388 error,
1389 format_timer(expired_deadline.into()),
1390 format_timer(now.into()),
1391 );
1392 error_cache.insert(error_string, ());
1393 }
1394 let (_dummy_lease, peer) = zx::EventPair::create();
1397 debug!(
1398 "bogus lease: {:?} fidl error [{}:{}]",
1399 peer.koid().unwrap(),
1400 file!(),
1401 line!()
1402 );
1403 notify_all(
1404 &mut timers,
1405 &peer,
1406 now,
1407 Some(TimerOpsError::Fidl(error)),
1408 &slack_histogram_prop,
1409 )
1410 .expect("notification succeeds");
1411 hrtimer_status = match timers.peek_deadline_as_boot() {
1412 None => None, Some(deadline) => Some(
1414 schedule_hrtimer(
1415 scope.clone(),
1416 now,
1417 &timer_proxy,
1418 deadline,
1419 snd.clone(),
1420 &timer_config,
1421 &schedule_delay_prop,
1422 &hrtimer_node,
1423 )
1424 .await,
1425 ),
1426 }
1427 }
1428 Cmd::AlarmDriverError {
1429 expired_deadline,
1430 error,
1431 timer_config_id,
1432 resolution_nanos,
1433 ticks,
1434 } => {
1435 let _i = ScopedInc::new(&alarm_driver_count);
1436
1437 trace::duration!("alarms", "Cmd::AlarmDriverError");
1438 let (_dummy_lease, peer) = zx::EventPair::create();
1439 debug!(
1440 "bogus lease: {:?} driver error. [{}:{}]",
1441 peer.koid().unwrap(),
1442 file!(),
1443 line!()
1444 );
1445 notify_all(
1446 &mut timers,
1447 &peer,
1448 now,
1449 Some(TimerOpsError::Driver(error)),
1450 &slack_histogram_prop,
1451 )
1452 .expect("notification succeeds");
1453 match error {
1454 fidl_fuchsia_hardware_hrtimer::DriverError::Canceled => {
1455 debug!(
1457 "wake_timer_loop: CANCELED timer at deadline: {}",
1458 format_timer(expired_deadline.into())
1459 );
1460 }
1461 _ => {
1462 error!(
1463 "wake_timer_loop: DRIVER SAYS: {:?}, deadline: {}, now: {}\n\ttimer_id={}\n\tresolution={}\n\tticks={}",
1464 error,
1465 format_timer(expired_deadline.into()),
1466 format_timer(now.into()),
1467 timer_config_id,
1468 resolution_nanos,
1469 ticks,
1470 );
1471 hrtimer_status = match timers.peek_deadline_as_boot() {
1475 None => None,
1476 Some(deadline) => Some(
1477 schedule_hrtimer(
1478 scope.clone(),
1479 now,
1480 &timer_proxy,
1481 deadline,
1482 snd.clone(),
1483 &timer_config,
1484 &schedule_delay_prop,
1485 &hrtimer_node,
1486 )
1487 .await,
1488 ),
1489 }
1490 }
1491 }
1492 }
1493 Cmd::UtcUpdated { transform } => {
1494 let _i = ScopedInc::new(&utc_update_count);
1495
1496 trace::duration!("alarms", "Cmd::UtcUpdated");
1497 debug!("wake_timer_loop: applying new clock transform: {transform:?}");
1498
1499 *utc_transform.borrow_mut() = transform;
1502
1503 if hrtimer_status.is_some() {
1506 log_long_op!(stop_hrtimer(&timer_proxy, &timer_config));
1507 hrtimer_status = match timers.peek_deadline_as_boot() {
1509 None => None,
1510 Some(deadline) => Some(
1511 schedule_hrtimer(
1512 scope.clone(),
1513 now,
1514 &timer_proxy,
1515 deadline,
1516 snd.clone(),
1517 &timer_config,
1518 &schedule_delay_prop,
1519 &hrtimer_node,
1520 )
1521 .await,
1522 ),
1523 }
1524 }
1525 }
1526 }
1527
1528 {
1529 let _i = ScopedInc::new(&status_count);
1530
1531 trace::duration!("timekeeper", "inspect");
1536 let now_formatted = format_timer(now.into());
1537 debug!("wake_timer_loop: now: {}", now_formatted);
1538 now_formatted_prop.set(&now_formatted);
1539
1540 let pending_timers_count: u64 =
1541 timers.timer_count().try_into().expect("always convertible");
1542 debug!("wake_timer_loop: currently pending timer count: {}", pending_timers_count);
1543 pending_timers_count_prop.set(pending_timers_count);
1544
1545 let pending_timers = format!("{}", timers);
1546 debug!("wake_timer_loop: currently pending timers: \n\t{}", timers);
1547 pending_timers_prop.set(&pending_timers);
1548
1549 let current_deadline: String = hrtimer_status
1550 .as_ref()
1551 .map(|s| format!("{}", format_timer(s.deadline.into())))
1552 .unwrap_or_else(|| "(none)".into());
1553 debug!("wake_timer_loop: current hardware timer deadline: {:?}", current_deadline);
1554 current_hw_deadline_prop.set(¤t_deadline);
1555
1556 let remaining_duration_until_alarm = hrtimer_status
1557 .as_ref()
1558 .map(|s| format!("{}", format_duration((s.deadline - now).into())))
1559 .unwrap_or_else(|| "(none)".into());
1560 debug!(
1561 "wake_timer_loop: remaining duration until alarm: {}",
1562 remaining_duration_until_alarm
1563 );
1564 remaining_until_alarm_prop.set(&remaining_duration_until_alarm);
1565 debug!("---");
1566 }
1567 }
1568
1569 log::info!("wake_timer_loop: exiting. This is only correct in test code.");
1572}
1573
1574async fn schedule_hrtimer(
1588 scope: fasync::ScopeHandle,
1589 now: fasync::BootInstant,
1590 hrtimer: &Box<dyn TimerOps>,
1591 deadline: fasync::BootInstant,
1592 mut command_send: mpsc::Sender<Cmd>,
1593 timer_config: &TimerConfig,
1594 _schedule_delay_histogram: &finspect::IntExponentialHistogramProperty,
1595 debug_node: &finspect::Node,
1596) -> TimerState {
1597 let timeout = std::cmp::max(zx::BootDuration::ZERO, deadline - now);
1598 trace::duration!("alarms", "schedule_hrtimer", "timeout" => timeout.into_nanos());
1599 let hrtimer_scheduled = zx::Event::create();
1601
1602 let schedule_count = debug_node.create_int("schedule", 0);
1603 let hrtimer_wait_count = debug_node.create_int("hrtimer_wait", 0);
1604 let wait_signaled_count = debug_node.create_int("wait_signaled", 0);
1605
1606 let _sc = ScopedInc::new(&schedule_count);
1607
1608 debug!(
1609 "schedule_hrtimer:\n\tnow: {}\n\tdeadline: {}\n\ttimeout: {}",
1610 format_timer(now.into()),
1611 format_timer(deadline.into()),
1612 format_duration(timeout),
1613 );
1614
1615 let slack = timer_config.pick_setting(timeout);
1616 let resolution_nanos = slack.resolution.into_nanos();
1617 let useful_ticks = std::cmp::max(MIN_USEFUL_TICKS, slack.ticks());
1620
1621 trace::instant!("alarms", "hrtimer:programmed",
1622 trace::Scope::Process,
1623 "resolution_ns" => resolution_nanos,
1624 "ticks" => useful_ticks
1625 );
1626 let timer_config_id = timer_config.id;
1627 let start_and_wait_fut = {
1628 let _sc = ScopedInc::new(&hrtimer_wait_count);
1629 hrtimer.start_and_wait(
1630 timer_config.id,
1631 &ffhh::Resolution::Duration(resolution_nanos),
1632 useful_ticks,
1633 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible"),
1634 )
1635 };
1636
1637 let hrtimer_scheduled_if_error =
1638 hrtimer_scheduled.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1639 let hrtimer_task = scope.spawn_local(async move {
1640 debug!("hrtimer_task: waiting for hrtimer driver response");
1641 trace::instant!("alarms", "hrtimer:started", trace::Scope::Process);
1642 let response = start_and_wait_fut.await;
1643 trace::instant!("alarms", "hrtimer:response", trace::Scope::Process);
1644 match response {
1645 Err(TimerOpsError::Fidl(e)) => {
1646 defer! {
1647 signal(&hrtimer_scheduled_if_error);
1649 }
1650 trace::instant!("alarms", "hrtimer:response:fidl_error", trace::Scope::Process);
1651 command_send
1652 .start_send(Cmd::AlarmFidlError { expired_deadline: now, error: e })
1653 .unwrap();
1654 }
1656 Err(TimerOpsError::Driver(e)) => {
1657 defer! {
1658 signal(&hrtimer_scheduled_if_error);
1661 }
1662 let driver_error_str = format!("{:?}", e);
1663 trace::instant!("alarms", "hrtimer:response:driver_error", trace::Scope::Process, "error" => &driver_error_str[..]);
1664 debug!("schedule_hrtimer: hrtimer driver error: {:?}", e);
1667 command_send
1668 .start_send(Cmd::AlarmDriverError {
1669 expired_deadline: now,
1670 error: e,
1671 timer_config_id,
1672 resolution_nanos,
1673 ticks: useful_ticks,
1674 })
1675 .unwrap();
1676 }
1678 Ok(keep_alive) => {
1679 trace::instant!("alarms", "hrtimer:response:alarm", trace::Scope::Process);
1680 debug!("hrtimer: got alarm response: {:?}", keep_alive);
1681 command_send
1683 .start_send(Cmd::Alarm { expired_deadline: deadline, keep_alive })
1684 .unwrap();
1685 }
1686 }
1687 debug!("hrtimer_task: exiting task.");
1688 trace::instant!("alarms", "hrtimer:task_exit", trace::Scope::Process);
1689 }).into();
1690 debug!("schedule_hrtimer: waiting for event to be signaled");
1691
1692 {
1693 let _i = ScopedInc::new(&wait_signaled_count);
1694 log_long_op!(wait_signaled(&hrtimer_scheduled));
1696 }
1697
1698 let now_after_signaled = fasync::BootInstant::now();
1699 let duration_until_scheduled: zx::BootDuration = (now_after_signaled - now).into();
1700 if duration_until_scheduled > zx::BootDuration::from_nanos(LONG_DELAY_NANOS) {
1701 trace::duration!("alarms", "schedule_hrtimer:unusual_duration",
1702 "duration" => duration_until_scheduled.into_nanos());
1703 warn!(
1704 "unusual duration until hrtimer scheduled: {}",
1705 format_duration(duration_until_scheduled)
1706 );
1707 }
1708 debug!("schedule_hrtimer: hrtimer wake alarm has been scheduled.");
1711 TimerState { task: hrtimer_task, deadline }
1712}
1713
1714fn notify_all(
1725 timers: &mut timers::Heap,
1726 lease_prototype: &zx::EventPair,
1727 reference_instant: fasync::BootInstant,
1728 timer_ops_error: Option<TimerOpsError>,
1729 _unusual_slack_histogram: &finspect::IntExponentialHistogramProperty,
1730) -> Result<usize> {
1731 trace::duration!("alarms", "notify_all");
1732 let now = fasync::BootInstant::now();
1733 let mut expired = 0;
1734 while let Some(timer_node) = timers.maybe_expire_earliest(reference_instant) {
1735 expired += 1;
1736 let deadline = timer_node.get_boot_deadline();
1738 let alarm = timer_node.id().alarm();
1739 let alarm_id = alarm.to_string();
1740 trace::duration!("alarms", "notify_all:notified", "alarm_id" => &*alarm_id);
1741 fuchsia_trace::flow_step!("alarms", "hrtimer_lifecycle", timers::get_trace_id(&alarm_id));
1742 let conn_id = timer_node.id().conn.clone();
1743 let slack: zx::BootDuration = deadline - now;
1744 if slack < zx::BootDuration::from_nanos(-LONG_DELAY_NANOS) {
1745 trace::duration!("alarms", "schedule_hrtimer:unusual_slack", "slack" => slack.into_nanos());
1746 warn!(
1748 "alarm id: {} had an unusually large slack: {}",
1749 alarm_id,
1750 format_duration(slack)
1751 );
1752 }
1753 if slack < zx::BootDuration::ZERO {
1754 }
1757 if let Some(ref err) = timer_ops_error {
1758 if !err.is_canceled() {
1761 timer_node.get_responder().send(alarm, Err(err.clone().into()));
1762 continue;
1763 }
1764 }
1765 debug!(
1766 concat!(
1767 "wake_alarm_loop: ALARM alarm_id: \"{}\"\n\tdeadline: {},\n\tconn_id: {:?},\n\t",
1768 "reference_instant: {},\n\tnow: {},\n\tslack: {}",
1769 ),
1770 alarm_id,
1771 format_timer(deadline.into()),
1772 conn_id,
1773 format_timer(reference_instant.into()),
1774 format_timer(now.into()),
1775 format_duration(slack),
1776 );
1777 let lease = lease_prototype.duplicate_handle(zx::Rights::SAME_RIGHTS).expect("infallible");
1778 trace::instant!("alarms", "notify", trace::Scope::Process, "alarm_id" => &alarm_id[..], "conn_id" => conn_id);
1779 if let Some(Err(e)) = timer_node.get_responder().send(alarm, Ok(lease)) {
1780 error!("could not signal responder: {:?}", e);
1781 }
1782 trace::instant!("alarms", "notified", trace::Scope::Process);
1783 }
1784 trace::instant!("alarms", "notify", trace::Scope::Process, "expired_count" => expired);
1785 debug!("notify_all: expired count: {}", expired);
1786 Ok(expired)
1787 }
1789
1790const HRTIMER_DIRECTORY: &str = "/dev/class/hrtimer";
1793
1794pub async fn connect_to_hrtimer_async() -> Result<ffhh::DeviceProxy> {
1803 debug!("connect_to_hrtimer: trying directory: {}", HRTIMER_DIRECTORY);
1804 let dir =
1805 fuchsia_fs::directory::open_in_namespace(HRTIMER_DIRECTORY, fidl_fuchsia_io::PERM_READABLE)
1806 .with_context(|| format!("Opening {}", HRTIMER_DIRECTORY))?;
1807 let path = device_watcher::watch_for_files(&dir)
1808 .await
1809 .with_context(|| format!("Watching for files in {}", HRTIMER_DIRECTORY))?
1810 .try_next()
1811 .await
1812 .with_context(|| format!("Getting a file from {}", HRTIMER_DIRECTORY))?;
1813 let path = path.ok_or_else(|| anyhow!("Could not find {}", HRTIMER_DIRECTORY))?;
1814 let path = path
1815 .to_str()
1816 .ok_or_else(|| anyhow!("Could not find a valid str for {}", HRTIMER_DIRECTORY))?;
1817 connect_to_named_protocol_at_dir_root::<ffhh::DeviceMarker>(&dir, path)
1818 .context("Failed to connect built-in service")
1819}
1820
1821#[cfg(test)]
1822mod tests {
1823 use super::*;
1824 use assert_matches::assert_matches;
1825 use diagnostics_assertions::{AnyProperty, assert_data_tree};
1826 use fuchsia_async::TestExecutor;
1827 use futures::select;
1828 use std::pin::pin;
1829 use test_case::test_case;
1830 use test_util::{assert_gt, assert_lt};
1831
1832 fn fake_wake_lease() -> fidl_fuchsia_power_system::LeaseToken {
1833 let (_lease, peer) = zx::EventPair::create();
1834 peer
1835 }
1836
1837 #[test]
1838 fn timer_duration_no_overflow() {
1839 let duration1 = TimerDuration {
1840 resolution: zx::BootDuration::from_seconds(100_000_000),
1841 ticks: u64::MAX,
1842 };
1843 let duration2 = TimerDuration {
1844 resolution: zx::BootDuration::from_seconds(110_000_000),
1845 ticks: u64::MAX,
1846 };
1847 assert_eq!(duration1, duration1);
1848 assert_eq!(duration2, duration2);
1849
1850 assert_lt!(duration1, duration2);
1851 assert_gt!(duration2, duration1);
1852 }
1853
1854 #[test_case(
1855 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1856 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1857 )]
1858 #[test_case(
1859 TimerDuration::new(zx::BootDuration::from_nanos(1), 10),
1860 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1861 )]
1862 #[test_case(
1863 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1864 TimerDuration::new(zx::BootDuration::from_nanos(1), 10)
1865 )]
1866 #[test_case(
1867 TimerDuration::new(zx::BootDuration::from_micros(1), 1),
1868 TimerDuration::new(zx::BootDuration::from_nanos(1), 1000)
1869 )]
1870 fn test_slack_eq(one: TimerDuration, other: TimerDuration) {
1871 assert_eq!(one, other);
1872 }
1873
1874 #[test_case(
1875 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1876 TimerDuration::new(zx::BootDuration::from_nanos(1), 2)
1877 )]
1878 #[test_case(
1879 TimerDuration::new(zx::BootDuration::from_nanos(1), 1),
1880 TimerDuration::new(zx::BootDuration::from_nanos(10), 1)
1881 )]
1882 fn test_slack_lt(one: TimerDuration, other: TimerDuration) {
1883 assert_lt!(one, other);
1884 }
1885
1886 #[test_case(
1887 TimerDuration::new(zx::BootDuration::from_nanos(1), 2),
1888 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1889 )]
1890 #[test_case(
1891 TimerDuration::new(zx::BootDuration::from_nanos(10), 1),
1892 TimerDuration::new(zx::BootDuration::from_nanos(1), 1)
1893 )]
1894 fn test_slack_gt(one: TimerDuration, other: TimerDuration) {
1895 assert_gt!(one, other);
1896 }
1897
1898 #[test_case(
1899 vec![zx::BootDuration::from_nanos(1)],
1900 100,
1901 zx::BootDuration::from_nanos(0),
1902 TimerDuration::new(zx::BootDuration::from_nanos(1), 1) ; "0ns becomes 1ns"
1903 )]
1904 #[test_case(
1905 vec![zx::BootDuration::from_nanos(1)],
1906 100,
1907 zx::BootDuration::from_nanos(50),
1908 TimerDuration::new(zx::BootDuration::from_nanos(1), 50) ; "Exact at 50x1ns"
1909 )]
1910 #[test_case(
1911 vec![zx::BootDuration::from_nanos(2)],
1912 100,
1913 zx::BootDuration::from_nanos(50),
1914 TimerDuration::new(zx::BootDuration::from_nanos(2), 25) ; "Exact at 25x2ns"
1915 )]
1916 #[test_case(
1917 vec![zx::BootDuration::from_nanos(3)],
1918 100,
1919 zx::BootDuration::from_nanos(50),
1920 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "Inexact at 51ns"
1922 )]
1923 #[test_case(
1924 vec![
1925 zx::BootDuration::from_nanos(3),
1926 zx::BootDuration::from_nanos(4)
1927 ],
1928 100,
1929 zx::BootDuration::from_nanos(50),
1930 TimerDuration::new(zx::BootDuration::from_nanos(3), 17) ; "3ns is a better resolution"
1931 )]
1932 #[test_case(
1933 vec![
1934 zx::BootDuration::from_nanos(1000),
1935 ],
1936 100,
1937 zx::BootDuration::from_nanos(50),
1938 TimerDuration::new(zx::BootDuration::from_nanos(1000), 1) ;
1939 "950ns negative slack is the best we can do"
1940 )]
1941 #[test_case(
1942 vec![
1943 zx::BootDuration::from_nanos(1),
1944 ],
1945 10,
1946 zx::BootDuration::from_nanos(50),
1947 TimerDuration::new(zx::BootDuration::from_nanos(1), 10) ;
1948 "10ns positive slack is the best we can do"
1949 )]
1950 #[test_case(
1951 vec![
1952 zx::BootDuration::from_millis(1),
1953 zx::BootDuration::from_micros(100),
1954 zx::BootDuration::from_micros(10),
1955 zx::BootDuration::from_micros(1),
1956 ],
1957 20, zx::BootDuration::from_micros(150),
1959 TimerDuration::new(zx::BootDuration::from_micros(10), 15) ;
1960 "Realistic case with resolutions from driver, should be 15us"
1961 )]
1962 #[test_case(
1963 vec![
1964 zx::BootDuration::from_millis(1),
1965 zx::BootDuration::from_micros(100),
1966 zx::BootDuration::from_micros(10),
1967 zx::BootDuration::from_micros(1),
1968 ],
1969 2000, zx::BootDuration::from_micros(6000),
1971 TimerDuration::new(zx::BootDuration::from_millis(1), 6) ;
1972 "Coarser exact unit wins"
1973 )]
1974 #[test_case(
1975 vec![
1976 zx::BootDuration::from_millis(1),
1977 zx::BootDuration::from_millis(10),
1978 zx::BootDuration::from_millis(100),
1979 ],
1980 1000,
1981 zx::BootDuration::from_micros(-10),
1982 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
1983 "Negative duration gets the smallest timer duration"
1984 )]
1985 #[test_case(
1986 vec![
1987 zx::BootDuration::from_millis(1),
1988 zx::BootDuration::from_millis(10),
1989 zx::BootDuration::from_millis(100),
1990 ],
1991 1000,
1992 zx::BootDuration::ZERO,
1993 TimerDuration::new(zx::BootDuration::from_millis(1), 1) ;
1994 "Zero duration gets the smallest timer duration"
1995 )]
1996 fn test_pick_setting(
1997 resolutions: Vec<zx::BootDuration>,
1998 max_ticks: u64,
1999 duration: zx::BootDuration,
2000 expected: TimerDuration,
2001 ) {
2002 let config = TimerConfig::new_from_data(MAIN_TIMER_ID as u64, &resolutions[..], max_ticks);
2003 let actual = config.pick_setting(duration);
2004
2005 assert_slack_eq(expected, actual);
2008 }
2009
2010 fn assert_slack_eq(expected: TimerDuration, actual: TimerDuration) {
2012 let slack = expected.duration() - actual.duration();
2013 assert_eq!(
2014 actual.resolution(),
2015 expected.resolution(),
2016 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2017 expected,
2018 format_duration(expected.duration()),
2019 actual,
2020 format_duration(actual.duration()),
2021 format_duration(slack)
2022 );
2023 assert_eq!(
2024 actual.ticks(),
2025 expected.ticks(),
2026 "\n\texpected: {} ({})\n\tactual : {} ({})\n\tslack: expected-actual={}",
2027 expected,
2028 format_duration(expected.duration()),
2029 actual,
2030 format_duration(actual.duration()),
2031 format_duration(slack)
2032 );
2033 }
2034
2035 #[derive(Debug)]
2036 enum FakeCmd {
2037 SetProperties {
2038 resolutions: Vec<zx::BootDuration>,
2039 max_ticks: i64,
2040 keep_alive: zx::EventPair,
2041 done: zx::Event,
2042 },
2043 }
2044
2045 use std::cell::RefCell;
2046 use std::rc::Rc;
2047
2048 fn fake_hrtimer_connection(
2054 scope: fasync::ScopeHandle,
2055 rcv: mpsc::Receiver<FakeCmd>,
2056 ) -> ffhh::DeviceProxy {
2057 debug!("fake_hrtimer_connection: entry.");
2058 let (hrtimer, mut stream) =
2059 fidl::endpoints::create_proxy_and_stream::<ffhh::DeviceMarker>();
2060 scope.clone().spawn_local(async move {
2061 let mut rcv = rcv.fuse();
2062 let timer_properties = Rc::new(RefCell::new(None));
2063 let wake_lease = Rc::new(RefCell::new(None));
2064
2065 let timer_running = Rc::new(RefCell::new(false));
2069
2070 loop {
2071 let timer_properties = timer_properties.clone();
2072 let wake_lease = wake_lease.clone();
2073 select! {
2074 cmd = rcv.next() => {
2075 debug!("fake_hrtimer_connection: cmd: {:?}", cmd);
2076 match cmd {
2077 Some(FakeCmd::SetProperties{ resolutions, max_ticks, keep_alive, done}) => {
2078 let mut timer_props = vec![];
2079 for v in 0..10 {
2080 timer_props.push(ffhh::TimerProperties {
2081 supported_resolutions: Some(
2082 resolutions.iter()
2083 .map(|d| ffhh::Resolution::Duration(d.into_nanos())).collect()),
2084 max_ticks: Some(max_ticks.try_into().unwrap()),
2085 supports_wait: Some(true),
2087 id: Some(v),
2088 ..Default::default()
2089 },
2090 );
2091 }
2092 *timer_properties.borrow_mut() = Some(timer_props);
2093 *wake_lease.borrow_mut() = Some(keep_alive);
2094 debug!("set timer properties to: {:?}", timer_properties);
2095 signal(&done);
2096 }
2097 e => {
2098 panic!("unrecognized command: {:?}", e);
2099 }
2100 }
2101 },
2103 event = stream.next() => {
2104 debug!("fake_hrtimer_connection: event: {:?}", event);
2105 if let Some(Ok(event)) = event {
2106 match event {
2107 ffhh::DeviceRequest::Start { responder, .. } => {
2108 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2109 *timer_running.borrow_mut() = true;
2110 responder.send(Ok(())).expect("");
2111 }
2112 ffhh::DeviceRequest::Stop { responder, .. } => {
2113 *timer_running.borrow_mut() = false;
2114 responder.send(Ok(())).expect("");
2115 }
2116 ffhh::DeviceRequest::GetTicksLeft { responder, .. } => {
2117 responder.send(Ok(1)).expect("");
2118 }
2119 ffhh::DeviceRequest::SetEvent { responder, .. } => {
2120 responder.send(Ok(())).expect("");
2121 }
2122 ffhh::DeviceRequest::StartAndWait { id, resolution, ticks, setup_event, responder, .. } => {
2123 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2124 *timer_running.borrow_mut() = true;
2125 debug!("fake_hrtimer_connection: starting timer: \"{}\", resolution: {:?}, ticks: {}", id, resolution, ticks);
2126 let ticks: i64 = ticks.try_into().unwrap();
2127 let sleep_duration = zx::BootDuration::from_nanos(ticks * match resolution {
2128 ffhh::Resolution::Duration(e) => e,
2129 _ => {
2130 error!("resolution has an unexpected value");
2131 1
2132 }
2133 });
2134 let timer_running_clone = timer_running.clone();
2135 scope.spawn_local(async move {
2136 signal(&setup_event);
2139
2140 fasync::Timer::new(sleep_duration).await;
2143 *timer_running_clone.borrow_mut() = false;
2144 responder.send(Ok(wake_lease.borrow().as_ref().unwrap().duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap())).unwrap();
2145 debug!("StartAndWait: hrtimer expired");
2146 });
2147 }
2148 ffhh::DeviceRequest::StartAndWait2 { responder, .. } => {
2149 assert!(!*timer_running.borrow(), "invariant broken: timer may not be running here");
2150 *timer_running.borrow_mut() = true;
2151 responder.send(Err(ffhh::DriverError::InternalError)).expect("");
2152 }
2153 ffhh::DeviceRequest::GetProperties { responder, .. } => {
2154 if (*timer_properties).borrow().is_none() {
2155 error!("timer_properties is empty, this is not what you want!");
2156 }
2157 responder
2158 .send(ffhh::Properties {
2159 timers_properties: (*timer_properties).borrow().clone(),
2160 ..Default::default()
2161 })
2162 .expect("");
2163 }
2164 ffhh::DeviceRequest::ReadTimer { responder, .. } => {
2165 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2166 }
2167 ffhh::DeviceRequest::ReadClock { responder, .. } => {
2168 responder.send(Err(ffhh::DriverError::NotSupported)).expect("");
2169 }
2170 ffhh::DeviceRequest::_UnknownMethod { .. } => todo!(),
2171 }
2172 }
2173 },
2174 }
2175 }
2176 });
2177 hrtimer
2178 }
2179
2180 fn clone_utc_clock(orig: &fxr::UtcClock) -> fxr::UtcClock {
2181 orig.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2182 }
2183
2184 struct TestContext {
2185 wake_proxy: fta::WakeAlarmsProxy,
2186 _scope: fasync::Scope,
2187 _cmd_tx: mpsc::Sender<FakeCmd>,
2188 utc_clock: fxr::UtcClock,
2190 utc_backstop: fxr::UtcInstant,
2191 }
2192
2193 impl TestContext {
2194 async fn new() -> Self {
2195 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(0)).await;
2196
2197 let scope = fasync::Scope::new();
2198 let utc_backstop = fxr::UtcInstant::from_nanos(1000);
2199 let utc_clock =
2200 fxr::UtcClock::create(zx::ClockOpts::empty(), Some(utc_backstop)).unwrap();
2201 let utc_clone = clone_utc_clock(&utc_clock);
2202 let (mut cmd_tx, wake_proxy) = {
2203 let (tx, rx) = mpsc::channel::<FakeCmd>(0);
2204 let hrtimer_proxy = fake_hrtimer_connection(scope.to_handle(), rx);
2205
2206 let inspector = finspect::component::inspector();
2207 let alarms = Rc::new(Loop::new(
2208 scope.to_handle(),
2209 hrtimer_proxy,
2210 inspector.root().create_child("test"),
2211 utc_clone,
2212 ));
2213
2214 let (proxy, stream) =
2215 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2216 scope.spawn_local(async move {
2217 serve(alarms, stream).await;
2218 });
2219 (tx, proxy)
2220 };
2221
2222 let (_wake_lease, peer) = zx::EventPair::create();
2223 let done = zx::Event::create();
2224 cmd_tx
2225 .start_send(FakeCmd::SetProperties {
2226 resolutions: vec![zx::Duration::from_nanos(1)],
2227 max_ticks: 100,
2228 keep_alive: peer,
2229 done: done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2230 })
2231 .unwrap();
2232
2233 assert_matches!(fasync::OnSignals::new(done, zx::Signals::EVENT_SIGNALED).await, Ok(_));
2235
2236 Self { wake_proxy, _scope: scope, _cmd_tx: cmd_tx, utc_clock, utc_backstop }
2237 }
2238 }
2239
2240 impl Drop for TestContext {
2241 fn drop(&mut self) {
2242 assert_matches!(TestExecutor::next_timer(), None, "Unexpected lingering timers");
2243 }
2244 }
2245
2246 #[fuchsia::test(allow_stalls = false)]
2247 async fn test_basic_timed_wait() {
2248 let ctx = TestContext::new().await;
2249
2250 let deadline = zx::BootInstant::from_nanos(100);
2251 let setup_done = zx::Event::create();
2252 let mut set_task = ctx.wake_proxy.set_and_wait(
2253 deadline.into(),
2254 fta::SetMode::NotifySetupDone(
2255 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2256 ),
2257 "Hello".into(),
2258 );
2259
2260 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task).await, Poll::Pending);
2261
2262 let mut setup_done_task =
2263 pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2264 assert_matches!(
2265 TestExecutor::poll_until_stalled(&mut setup_done_task).await,
2266 Poll::Ready(Ok(_)),
2267 "Setup event not triggered after scheduling an alarm"
2268 );
2269
2270 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(100)).await;
2271 assert_matches!(TestExecutor::poll_until_stalled(set_task).await, Poll::Ready(Ok(Ok(_))));
2272 }
2273
2274 #[fuchsia::test(allow_stalls = false)]
2275 async fn test_basic_timed_wait_notify() {
2276 const ALARM_ID: &str = "Hello";
2277 let ctx = TestContext::new().await;
2278
2279 let (notifier_client, mut notifier_stream) =
2280 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2281 let setup_done = zx::Event::create();
2282 assert_matches!(
2283 ctx.wake_proxy
2284 .set(
2285 notifier_client,
2286 fidl::BootInstant::from_nanos(2),
2287 fta::SetMode::NotifySetupDone(
2288 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap()
2289 ),
2290 ALARM_ID,
2291 )
2292 .await,
2293 Ok(Ok(()))
2294 );
2295
2296 let mut done_task = pin!(fasync::OnSignals::new(setup_done, zx::Signals::EVENT_SIGNALED));
2297 assert_matches!(
2298 TestExecutor::poll_until_stalled(&mut done_task).await,
2299 Poll::Ready(Ok(_)),
2300 "Setup event not triggered after scheduling an alarm"
2301 );
2302
2303 let mut next_task = notifier_stream.next();
2304 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2305
2306 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2307 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2308
2309 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(2)).await;
2310 assert_matches!(
2311 TestExecutor::poll_until_stalled(next_task).await,
2312 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2313 );
2314 }
2315
2316 #[fuchsia::test(allow_stalls = false)]
2317 async fn test_two_alarms_same() {
2318 const DEADLINE_NANOS: i64 = 100;
2319
2320 let ctx = TestContext::new().await;
2321
2322 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2323 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2324 fta::SetMode::KeepAlive(fake_wake_lease()),
2325 "Hello1".into(),
2326 );
2327 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2328 fidl::BootInstant::from_nanos(DEADLINE_NANOS),
2329 fta::SetMode::KeepAlive(fake_wake_lease()),
2330 "Hello2".into(),
2331 );
2332
2333 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2334 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2335
2336 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2337
2338 assert_matches!(
2339 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2340 Poll::Ready(Ok(Ok(_)))
2341 );
2342 assert_matches!(
2343 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2344 Poll::Ready(Ok(Ok(_)))
2345 );
2346 }
2347
2348 #[fuchsia::test(allow_stalls = false)]
2349 async fn test_two_alarms_same_notify() {
2350 const DEADLINE_NANOS: i64 = 100;
2351 const ALARM_ID_1: &str = "Hello1";
2352 const ALARM_ID_2: &str = "Hello2";
2353
2354 let ctx = TestContext::new().await;
2355
2356 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2357 let (notifier_client, notifier_stream) =
2358 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2359 assert_matches!(
2360 ctx.wake_proxy
2361 .set(
2362 notifier_client,
2363 fidl::BootInstant::from_nanos(deadline_nanos),
2364 fta::SetMode::KeepAlive(fake_wake_lease()),
2365 alarm_id,
2366 )
2367 .await,
2368 Ok(Ok(()))
2369 );
2370 notifier_stream
2371 };
2372
2373 let mut notifier_1 = schedule(DEADLINE_NANOS, ALARM_ID_1).await;
2374 let mut notifier_2 = schedule(DEADLINE_NANOS, ALARM_ID_2).await;
2375
2376 let mut next_task_1 = notifier_1.next();
2377 let mut next_task_2 = notifier_2.next();
2378
2379 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2380 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2381
2382 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(DEADLINE_NANOS)).await;
2383
2384 assert_matches!(
2385 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2386 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_1
2387 );
2388 assert_matches!(
2389 TestExecutor::poll_until_stalled(&mut next_task_2).await,
2390 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID_2
2391 );
2392
2393 assert_matches!(
2394 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2395 Poll::Ready(None)
2396 );
2397 assert_matches!(
2398 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2399 Poll::Ready(None)
2400 );
2401 }
2402
2403 #[test_case(100, 200 ; "push out")]
2404 #[test_case(200, 100 ; "pull in")]
2405 #[fuchsia::test(allow_stalls = false)]
2406 async fn test_two_alarms_different(
2407 first_deadline_nanos: i64,
2409 second_deadline_nanos: i64,
2411 ) {
2412 let ctx = TestContext::new().await;
2413
2414 let mut set_task_1 = ctx.wake_proxy.set_and_wait(
2415 fidl::BootInstant::from_nanos(first_deadline_nanos),
2416 fta::SetMode::KeepAlive(fake_wake_lease()),
2417 "Hello1".into(),
2418 );
2419 let mut set_task_2 = ctx.wake_proxy.set_and_wait(
2420 fidl::BootInstant::from_nanos(second_deadline_nanos),
2421 fta::SetMode::KeepAlive(fake_wake_lease()),
2422 "Hello2".into(),
2423 );
2424
2425 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2426 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2427
2428 let mut tasks = [(first_deadline_nanos, set_task_1), (second_deadline_nanos, set_task_2)];
2430 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2431 let [mut first_task, mut second_task] = tasks;
2432
2433 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(first_task.0)).await;
2435 assert_matches!(
2436 TestExecutor::poll_until_stalled(&mut first_task.1).await,
2437 Poll::Ready(Ok(Ok(_)))
2438 );
2439 assert_matches!(TestExecutor::poll_until_stalled(&mut second_task.1).await, Poll::Pending);
2440
2441 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(second_task.0)).await;
2442 assert_matches!(
2443 TestExecutor::poll_until_stalled(&mut second_task.1).await,
2444 Poll::Ready(Ok(Ok(_)))
2445 );
2446 }
2447
2448 #[test_case(100, 200 ; "push out")]
2449 #[test_case(200, 100 ; "pull in")]
2450 #[fuchsia::test(allow_stalls = false)]
2451 async fn test_two_alarms_different_notify(
2452 first_deadline_nanos: i64,
2454 second_deadline_nanos: i64,
2456 ) {
2457 const ALARM_ID_1: &str = "Hello1";
2458 const ALARM_ID_2: &str = "Hello2";
2459
2460 let ctx = TestContext::new().await;
2461
2462 let schedule = async |deadline_nanos: i64, alarm_id: &str| {
2463 let (notifier_client, notifier_stream) =
2464 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2465 assert_matches!(
2466 ctx.wake_proxy
2467 .set(
2468 notifier_client,
2469 fidl::BootInstant::from_nanos(deadline_nanos),
2470 fta::SetMode::KeepAlive(fake_wake_lease()),
2471 alarm_id,
2472 )
2473 .await,
2474 Ok(Ok(()))
2475 );
2476 notifier_stream
2477 };
2478
2479 let mut notifier_all = futures::stream::select_all([
2481 schedule(first_deadline_nanos, ALARM_ID_1).await,
2482 schedule(second_deadline_nanos, ALARM_ID_2).await,
2483 ]);
2484 let [(early_ns, early_alarm), (later_ns, later_alarm)] = {
2485 let mut tasks =
2486 [(first_deadline_nanos, ALARM_ID_1), (second_deadline_nanos, ALARM_ID_2)];
2487 tasks.sort_by(|a, b| a.0.cmp(&b.0));
2488 tasks
2489 };
2490
2491 let mut next_task = notifier_all.next();
2493 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2494
2495 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(early_ns)).await;
2496 assert_matches!(
2497 TestExecutor::poll_until_stalled(next_task).await,
2498 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == early_alarm
2499 );
2500
2501 let mut next_task = notifier_all.next();
2502 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task).await, Poll::Pending);
2503
2504 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(later_ns)).await;
2505 assert_matches!(
2506 TestExecutor::poll_until_stalled(next_task).await,
2507 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == later_alarm
2508 );
2509 assert_matches!(
2510 TestExecutor::poll_until_stalled(notifier_all.next()).await,
2511 Poll::Ready(None)
2512 );
2513 }
2514
2515 #[fuchsia::test(allow_stalls = false)]
2516 async fn test_alarm_immediate() {
2517 let ctx = TestContext::new().await;
2518 let mut set_task = ctx.wake_proxy.set_and_wait(
2519 fidl::BootInstant::INFINITE_PAST,
2520 fta::SetMode::KeepAlive(fake_wake_lease()),
2521 "Hello1".into(),
2522 );
2523 assert_matches!(
2524 TestExecutor::poll_until_stalled(&mut set_task).await,
2525 Poll::Ready(Ok(Ok(_)))
2526 );
2527 }
2528
2529 #[fuchsia::test(allow_stalls = false)]
2530 async fn test_alarm_immediate_notify() {
2531 const ALARM_ID: &str = "Hello";
2532 let ctx = TestContext::new().await;
2533
2534 let (notifier_client, mut notifier_stream) =
2535 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2536
2537 let mut set_task = ctx.wake_proxy.set(
2538 notifier_client,
2539 fidl::BootInstant::INFINITE_PAST,
2540 fta::SetMode::KeepAlive(fake_wake_lease()),
2541 ALARM_ID,
2542 );
2543 assert_matches!(
2544 TestExecutor::poll_until_stalled(&mut set_task).await,
2545 Poll::Ready(Ok(Ok(_)))
2546 );
2547 assert_matches!(
2548 TestExecutor::poll_until_stalled(notifier_stream.next()).await,
2549 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2550 );
2551 }
2552
2553 #[test_case(200, 100 ; "pull in")]
2556 #[test_case(100, 200 ; "push out")]
2557 #[test_case(100, 100 ; "replace with the same deadline")]
2558 #[fuchsia::test(allow_stalls = false)]
2559 async fn test_reschedule(initial_deadline_nanos: i64, override_deadline_nanos: i64) {
2560 const ALARM_ID: &str = "Hello";
2561
2562 let ctx = TestContext::new().await;
2563
2564 let schedule = |deadline_nanos: i64| {
2565 let setup_done = zx::Event::create();
2566 let task = ctx.wake_proxy.set_and_wait(
2567 fidl::BootInstant::from_nanos(deadline_nanos),
2568 fta::SetMode::NotifySetupDone(
2569 setup_done.duplicate_handle(zx::Rights::SAME_RIGHTS).unwrap(),
2570 ),
2571 ALARM_ID.into(),
2572 );
2573 (task, setup_done)
2574 };
2575
2576 let (mut set_task_1, setup_done_1) = schedule(initial_deadline_nanos);
2579 fasync::OnSignals::new(setup_done_1, zx::Signals::EVENT_SIGNALED).await.unwrap();
2580 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_1).await, Poll::Pending);
2581
2582 let (mut set_task_2, setup_done_2) = schedule(override_deadline_nanos);
2585 fasync::OnSignals::new(setup_done_2, zx::Signals::EVENT_SIGNALED).await.unwrap();
2586 assert_matches!(
2587 TestExecutor::poll_until_stalled(&mut set_task_1).await,
2588 Poll::Ready(Ok(Err(fta::WakeAlarmsError::Dropped)))
2589 );
2590 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2591
2592 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos - 1))
2594 .await;
2595 assert_matches!(TestExecutor::poll_until_stalled(&mut set_task_2).await, Poll::Pending);
2596 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(override_deadline_nanos))
2597 .await;
2598 assert_matches!(
2599 TestExecutor::poll_until_stalled(&mut set_task_2).await,
2600 Poll::Ready(Ok(Ok(_)))
2601 );
2602
2603 assert_data_tree!(finspect::component::inspector(), root: {
2606 test: {
2607 hardware: {
2608 current_deadline: "(none)",
2610 remaining_until_alarm: "(none)",
2611 },
2612 now_formatted: format!("{override_deadline_nanos}ns ({override_deadline_nanos})"),
2613 now_ns: override_deadline_nanos,
2614 pending_timers: "Boot:\n\t\n\tUTC:\n\t",
2615 pending_timers_count: 0u64,
2616 requested_deadlines_ns: AnyProperty,
2617 schedule_delay_ns: AnyProperty,
2618 slack_ns: AnyProperty,
2619 boot_deadlines_count: AnyProperty,
2620 utc_deadlines_count: AnyProperty,
2621 debug_node: contains {},
2622 },
2623 });
2624 }
2625
2626 #[fuchsia::test(allow_stalls = false)]
2629 async fn test_reschedule_notify() {
2630 const ALARM_ID: &str = "Hello";
2631 const INITIAL_DEADLINE_NANOS: i64 = 100;
2632 const OVERRIDE_DEADLINE_NANOS: i64 = 200;
2633
2634 let ctx = TestContext::new().await;
2635
2636 let schedule = async |deadline_nanos: i64| {
2637 let (notifier_client, notifier_stream) =
2638 fidl::endpoints::create_request_stream::<fta::NotifierMarker>();
2639 assert_matches!(
2640 ctx.wake_proxy
2641 .set(
2642 notifier_client,
2643 fidl::BootInstant::from_nanos(deadline_nanos),
2644 fta::SetMode::KeepAlive(fake_wake_lease()),
2645 ALARM_ID.into(),
2646 )
2647 .await,
2648 Ok(Ok(()))
2649 );
2650 notifier_stream
2651 };
2652
2653 let mut notifier_1 = schedule(INITIAL_DEADLINE_NANOS).await;
2654 let mut next_task_1 = notifier_1.next();
2655 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_1).await, Poll::Pending);
2656
2657 let mut notifier_2 = schedule(OVERRIDE_DEADLINE_NANOS).await;
2658 let mut next_task_2 = notifier_2.next();
2659 assert_matches!(TestExecutor::poll_until_stalled(&mut next_task_2).await, Poll::Pending);
2660
2661 assert_matches!(
2663 TestExecutor::poll_until_stalled(&mut next_task_1).await,
2664 Poll::Ready(Some(Ok(fta::NotifierRequest::NotifyError { alarm_id, error, .. }))) if alarm_id == ALARM_ID && error == fta::WakeAlarmsError::Dropped
2665 );
2666 assert_matches!(
2667 TestExecutor::poll_until_stalled(notifier_1.next()).await,
2668 Poll::Ready(None)
2669 );
2670
2671 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(OVERRIDE_DEADLINE_NANOS))
2673 .await;
2674 assert_matches!(
2675 TestExecutor::poll_until_stalled(next_task_2).await,
2676 Poll::Ready(Some(Ok(fta::NotifierRequest::Notify { alarm_id, .. }))) if alarm_id == ALARM_ID
2677 );
2678 assert_matches!(
2679 TestExecutor::poll_until_stalled(notifier_2.next()).await,
2680 Poll::Ready(None)
2681 );
2682 }
2683
2684 #[fuchsia::test(allow_stalls = false)]
2687 async fn test_fidl_error_on_reschedule() {
2688 const DEADLINE_NANOS: i64 = 100;
2689
2690 let (wake_proxy, _stream) =
2691 fidl::endpoints::create_proxy_and_stream::<fta::WakeAlarmsMarker>();
2692 drop(_stream);
2693
2694 assert_matches!(
2695 wake_proxy
2696 .set_and_wait(
2697 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2698 fta::SetMode::KeepAlive(fake_wake_lease()),
2699 "hello1".into(),
2700 )
2701 .await,
2702 Err(fidl::Error::ClientChannelClosed { .. })
2703 );
2704
2705 assert_matches!(
2706 wake_proxy
2707 .set_and_wait(
2708 zx::BootInstant::from_nanos(DEADLINE_NANOS).into(),
2709 fta::SetMode::KeepAlive(fake_wake_lease()),
2710 "hello2".into(),
2711 )
2712 .await,
2713 Err(fidl::Error::ClientChannelClosed { .. })
2714 );
2715 }
2716
2717 #[fuchsia::test(allow_stalls = false)]
2720 async fn test_set_and_wait_utc() {
2721 const ALARM_ID: &str = "Hello_set_and_wait_utc";
2722 let ctx = TestContext::new().await;
2723
2724 let now_boot = fasync::BootInstant::now();
2725 ctx.utc_clock
2726 .update(
2727 zx::ClockUpdate::builder()
2728 .absolute_value(now_boot.into(), ctx.utc_backstop)
2729 .build(),
2730 )
2731 .unwrap();
2732
2733 let timestamp_utc = ctx.utc_backstop + fxr::UtcDuration::from_nanos(2);
2734 let mut wake_fut = ctx.wake_proxy.set_and_wait_utc(
2735 &fta::InstantUtc { timestamp_utc: timestamp_utc.into_nanos() },
2736 fta::SetMode::KeepAlive(fake_wake_lease()),
2737 ALARM_ID,
2738 );
2739
2740 assert_matches!(TestExecutor::poll_until_stalled(&mut wake_fut).await, Poll::Pending);
2742
2743 ctx.utc_clock
2745 .update(
2746 zx::ClockUpdate::builder()
2747 .absolute_value(
2748 now_boot.into(),
2749 ctx.utc_backstop + fxr::UtcDuration::from_nanos(100),
2750 )
2751 .build(),
2752 )
2753 .unwrap();
2754
2755 TestExecutor::advance_to(fasync::MonotonicInstant::from_nanos(1)).await;
2757 assert_matches!(TestExecutor::poll_until_stalled(wake_fut).await, Poll::Ready(_));
2758 }
2759}