pocket_watch/step

This module is intended for cases where you have multiple steps in a time-consuming operation, and you’d like to figure out which step(s) are your bottleneck.

Examples:

Log each step’s timing as it runs:

let step.Return(wabble, _) =
  step.collect({
    use <- step.simple("loading wibble") // using `simple` callback for logging
    let wibble = load_wibble()
    // pocket_watch [loading wibble]: took 80ms

    use <- step.next("parsing wibble")
    let wobble = wobble.parse_wibble(wibble)
    // pocket_watch [parsing wibble]: took 150ms

    use <- step.next("wobble -> wabble conversion")
    let wabble = wobble.to_wabble(wobble)
    // pocket_watch [wobble -> wabble conversion]: took 500ms

    step.finish(wabble)
  })

// do something with the returned wabble

Find the slowest step as a percentage of the total time, without logging:

let step.Return(_wabble, steps:) =
  step.collect({
    use <- step.next("loading wibble") // no callback has been provided, so no logging will be done
    let wibble = load_wibble()

    use <- step.next("parsing wibble")
    let wobble = wobble.parse_wibble(wibble)

    use <- step.next("wobble -> wabble conversion")
    let wabble = wobble.to_wabble(wobble)

    step.finish(wabble)
  })

steps |> list.sort(step.compare) |> step.percent(0) |> list.last |> echo
// Ok(Step("wobble -> wabble conversion", "68%"))

Find the total time of multiple steps:

let step.Return(_wabble, steps:) =
  step.collect({
    use <- step.next("loading wibble")
    let wibble = load_wibble()

    use <- step.next("parsing wibble")
    let wobble = wobble.parse_wibble(wibble)

    use <- step.next("wobble -> wabble conversion")
    let wabble = wobble.to_wabble(wobble)

    step.finish(wabble)
  })

steps |> step.total(", ") |> step.humanise |> echo
// Step("[loading wibble], [parsing wibble], [wobble -> wabble conversion]", "730ms")

Specify multiple callbacks:

let print_nanoseconds = fn(label, elapsed) {
  io.println_error(
    label <> " took " <> float.to_string(elapsed) <> " nanoseconds",
  )
}

let print_if_slow = fn(label, elapsed) {
  case elapsed >. 250.0e6 {
    False -> Nil
    True ->
      io.println_error(
        "warning: "
        <> label
        <> " took more than 250ms ("
        <> humanise.nanoseconds_float(elapsed)
        <> ")",
      )
  }
}

step.collect({
  use <- step.simple("loading wibble")
  let wibble = load_wibble()
  // pocket_watch [loading wibble]: took 80ms

  use <- step.callback_ns("parsing wibble", print_nanoseconds)
  let wobble = parse_wibble(wibble)
  // parsing wibble took 150000000.0 nanoseconds

  use <- step.callback_ns("wobble -> wabble conversion", print_if_slow)
  let wabble = wobble_to_wabble(wobble)
  // warning: wobble -> wabble conversion took more than 250ms (500ms)

  step.finish(wabble)
})

pub type Return(return) {
  Return(return: return, steps: List(Step(Float)))
}

pub type Step(time) {
  Step(label: String, elapsed: time)
}

pub opaque type StepTracker(return)

pub fn callback(
  label label: String,
  with callback: fn(String, String) -> Nil,
  continue continue: fn() -> StepTracker(return),
) -> StepTracker(return)

let print_time = fn(label, elapsed) {
  io.println_error(label <> " took " <> elapsed)
}

step.collect({
  use <- step.callback("test", with: print_time)

  process.sleep(1000)
  // test took 1.0s

  use <- step.next("another test")

  process.sleep(2000)
  // another test took 2.0s

  step.finish(Nil)
})

pub fn callback_ns(
  label label: String,
  with callback: fn(String, Float) -> Nil,
  continue continue: fn() -> StepTracker(return),
) -> StepTracker(return)

let print_time = fn(label, elapsed) {
  io.println_error(label <> " took " <> float.to_string(elapsed /. 1_000_000.0) <> "ms")
}

step.collect({
  use <- step.callback_ns("test", with: print_time)

  process.sleep(1000)
  // test took 1000.0ms

  use <- step.next("another test")

  process.sleep(2000)
  // another test took 2000.0ms

  step.finish(Nil)
})

pub fn collect(tracker: StepTracker(return)) -> Return(return)

let Return(return: Nil, steps:) = step.collect({
  use <- step.next("step")

  step.finish(Nil)
})

pub fn compare(
  left: Step(Float),
  right: Step(Float),
) -> order.Order

pub fn finish(return return: return) -> StepTracker(return)

step.collect({
  use <- step.next("a step")

  step.finish("a value")
}).return
|> io.println // a value

pub fn humanise(step: Step(Float)) -> Step(String)

pub fn next(
  label new_label: String,
  continue continue: fn() -> StepTracker(return),
) -> StepTracker(return)

let step.Return(Nil, steps:) =
  step.collect({
    use <- step.next("test")

    process.sleep(1000)
    // nothing is logged here

    use <- step.next("another test")

    process.sleep(2000)
    // or here

    step.finish(Nil)
  })

list.each(steps, fn(s) {
  io.println(s.label <> ": " <> humanise.nanoseconds_float(s.elapsed))
})
// test: 1.0s
// another test: 2.0s

pub fn percent(
  steps: List(Step(Float)),
  precision: Int,
) -> List(Step(String))

pub fn simple(
  label label: String,
  continue continue: fn() -> StepTracker(return),
) -> StepTracker(return)

step.collect({
  use <- step.simple("test")

  process.sleep(1000)
  // pocket_watch [test]: took 1.0s

  use <- step.next("another test")

  process.sleep(2000)
  // pocket_watch [another test]: took 2.0s

  step.finish(Nil)
})

pub fn total(
  steps: List(Step(Float)),
  separator: String,
) -> Step(Float)

["first", "second", "third"]

"[first], [second], [third]"