Timing.pudu

Pudu123 lines5.1 KB

Copy pathGitHub ↗

1/** @Log.Timing.Operation — measures a unit of work and logs its outcome */2module PuduLangLog.Timing34import Std.Decimal as Decimal5import Std.Sync as Sync6import Std.Time as Time7import PuduLangLog.Domain.Levels as Levels8import PuduLangLog.Failure as Failure9import PuduLangLog as Log10import PuduLangLog.Logger as Logger1112/** @Log.Timing.Operation — a timed unit of work awaiting its outcome */13export type Operation = {14  logger: Logger.Logger,15  template: Str,16  arguments: Array[Log.Value],17  started: Int,18  completion: Log.Level,19  abandonment: Log.Level,20  warningAfter: Option[Int],21  properties: Array[(Str, Log.Value)],22  finished: Sync.Cell[Bool],23  elapsed: fn() -> Int24}2526/// Starts timing an operation described by a template and its arguments. Nothing is written until27/// it is completed or abandoned.28export fn begin(logger: &Logger.Logger, template: Str, arguments: Array[Log.Value]) -> Operation {29  beginWith(logger, template, arguments, fn() -> Int { Time.elapsed() })30}3132/// Starts timing with a millisecond counter of the caller's choice, such as a test's.33export fn beginWith(logger: &Logger.Logger, template: Str, arguments: Array[Log.Value], elapsed: fn() -> Int) -> Operation {34  Operation {35    logger: *logger,36    template: template,37    arguments: arguments,38    started: elapsed(),39    completion: Log.Information,40    abandonment: Log.Warning,41    warningAfter: None,42    properties: [],43    finished: Sync.cell(false),44    elapsed: elapsed45  }46}4748/// Runs an action as a completed operation and answers its value.49export fn run[T](logger: &Logger.Logger, template: Str, arguments: Array[Log.Value], action: fn() -> T) -> T {50  let operation = begin(logger, template, arguments)51  let answer = action()52  operation.complete()53  answer54}5556/// Runs an action whose `Err` abandons the operation with the error as its failure, and answers its57/// result.58export fn runResult[T, E](logger: &Logger.Logger, template: Str, arguments: Array[Log.Value], kind: Str, action: fn() -> Result[T, E]) -> Result[T, E] {59  let operation = begin(logger, template, arguments)60  let answer = action()61  match &answer {62    case Ok(_) => operation.complete()63    case Err(problem) => operation.abandonWith(Failure.from(kind, problem))64  }65  answer66}6768/** @Log.Timing.Measuring — how an operation ends and is reported */69export trait Measuring {70  fn at(self: &Self, completion: Log.Level, abandonment: Log.Level) -> Self71  fn warnAfter(self: &Self, millis: Int) -> Self72  fn enrichWith(self: &Self, name: Str, held: Log.Value) -> Self73  fn complete(self: &Self) -> ()74  fn completeWith(self: &Self, name: Str, held: Log.Value) -> ()75  fn abandon(self: &Self) -> ()76  fn abandonWith(self: &Self, failure: Log.Failure) -> ()77  fn cancel(self: &Self) -> ()78}7980impl Measuring for Operation {81  /// The operation reporting completion and abandonment at other levels.82  fn at(self: &Self, completion: Log.Level, abandonment: Log.Level) -> Self { Operation{..*self, completion: completion, abandonment: abandonment} }8384  /// The operation reporting a completion slower than `millis` at `Warning` or above.85  fn warnAfter(self: &Self, millis: Int) -> Self { Operation{..*self, warningAfter: Some(millis)} }8687  /// The operation adding a property to its outcome event.88  fn enrichWith(self: &Self, name: Str, held: Log.Value) -> Self { Operation{..*self, properties: self.properties.push((name, held))} }8990  /// Writes `<template> completed in <Elapsed> ms` at the completion level.91  fn complete(self: &Self) -> () { finish(self, "completed", None, []) }9293  /// Writes the completion with one more property, such as a result count.94  fn completeWith(self: &Self, name: Str, held: Log.Value) -> () { finish(self, "completed", None, [(name, held)]) }9596  /// Writes `<template> abandoned in <Elapsed> ms` at the abandonment level.97  fn abandon(self: &Self) -> () { finish(self, "abandoned", None, []) }9899  /// Writes the abandonment carrying a failure.100  fn abandonWith(self: &Self, failure: Log.Failure) -> () { finish(self, "abandoned", Some(failure), []) }101102  /// Ends the operation without writing anything.103  fn cancel(self: &Self) -> () { let _ended = Sync.swap(&self.finished, true) }104}105106/// Writes the outcome once: `Outcome` and `Elapsed` follow the template's own arguments, and the107/// operation's extra properties are attached to the event.108fn finish(operation: &Operation, outcome: Str, failure: Option[Log.Failure], extra: Array[(Str, Log.Value)]) -> () {109  if Sync.swap(&operation.finished, true) == Ok(true) { return () }110  let millis = (operation.elapsed)() - operation.started111  let slow = match operation.warningAfter {112    case Some(limit) => millis > limit113    case None => false114  }115  let base = if outcome == "completed" { operation.completion } else { operation.abandonment }116  let level = if slow { Levels.stricter(base, Log.Warning) } else { base }117  var logger = operation.logger118  for property in operation.properties.concat(extra) { logger = logger.forContext(property[0], property[1]) }119  let elapsed = Log.Scalar(Log.Real(Decimal.toFloat64(Decimal.fromInt(millis))))120  let arguments = operation.arguments.push(Log.Scalar(Log.Text(outcome))).push(elapsed)121  let _written = logger.tryWrite(level, failure, operation.template + " \{Outcome:l\} in \{Elapsed:0.0\} ms", arguments)122}123