message: Track event processing length as metric
diff: @@ -38,7 +38,7 @@ use std::{
  use datasize::DataSize;
  use futures::{future::BoxFuture, FutureExt};
  -use prometheus::{self, IntCounter, Registry};
  +use prometheus::{self, Histogram, HistogramOpts, IntCounter, Registry};
  use quanta::IntoNanoseconds;
  use tracing::{debug, debug_span, info, trace, warn};
  use tracing_futures::Instrument;
  @@ -207,6 +207,9 @@ struct RunnerMetrics {
  /// Total number of events processed.
  events: IntCounter,
  + /// Histogram of how long it took to dispatch an event.
  + event_dispatch_duration: Histogram,
  +
  /// Handle to the metrics registry, in case we need to unregister.
  registry: Registry,
  }
  @@ -215,10 +218,42 @@ impl RunnerMetrics {
  /// Create and register new runner metrics.
  fn new(registry: &Registry) -> Result<Self, prometheus::Error> {
  let events = IntCounter::new("runner_events", "total event count")?;
  +
  + // Create an event dispatch histogram, putting extra emphasis on the area between 1-10 us.
  + let event_dispatch_duration = Histogram::with_opts(
  + HistogramOpts::new(
  + "event_dispatch_duration",
  + "duration of complete dispatch of a single event in nanoseconds",
  + )
  + .buckets(vec![
  + 100.0,
  + 500.0,
  + 1_000.0,
  + 5_000.0,
  + 10_000.0,
  + 20_000.0,
  + 50_000.0,
  + 100_000.0,
  + 200_000.0,
  + 300_000.0,
  + 400_000.0,
  + 500_000.0,
  + 600_000.0,
  + 700_000.0,
  + 800_000.0,
  + 900_000.0,
  + 1_000_000.0,
  + 2_000_000.0,
  + 5_000_000.0,
  + ]),
  + )?;
  +
  registry.register(Box::new(events.clone()))?;
  + registry.register(Box::new(event_dispatch_duration.clone()))?;
  Ok(RunnerMetrics {
  events,
  + event_dispatch_duration,
  registry: registry.clone(),
  })
  }
  @@ -228,7 +263,10 @@ impl Drop for RunnerMetrics {
  fn drop(&mut self) {
  self.registry
  .unregister(Box::new(self.events.clone()))
  - .expect("did not expect deregistering metrics to fail")
  + .expect("did not expect deregistering events to fail");
  + self.registry
  + .unregister(Box::new(self.event_dispatch_duration.clone()))
  + .expect("did not expect deregistering event_dispatch_duration to fail");
  }
  }
  @@ -345,14 +383,18 @@ where
  let start = self.clock.start();
  let effects = self.reactor.dispatch_event(effect_builder, rng, event);
  let end = self.clock.end();
  - let delta = self.clock.delta(start, end);
  + // Warn if processing took a long time, record to histogram.
  + let delta = self.clock.delta(start, end);
  if delta > DISPATCH_EVENT_THRESHOLD {
  warn!(
  ns = delta.into_nanos(),
  "previous event took very long to dispatch"
  );
  }
  + self.metrics
  + .event_dispatch_duration
  + .observe(delta.into_nanos() as f64);
  drop(inner_enter);
  