@@ 1,12 1,35 @@
+(** Call a function and log how long it takes. Remembers the timings
+ to report on in an aggregated summary, and can optionally also log
+ immediately on function return.
+*)
signature TIMING = sig
+ (** Label for a specific function invocation point.
+ *)
type tag = string
-
+
+ (** Call the given function, time how long it takes, and record
+ the time against the given tag. The time is also logged
+ immediately if DEBUG log level is active.
+ *)
val timed : tag -> (unit -> 'a) -> 'a
+ (** Call the given function, time how long it takes, and record
+ the time against the given tag. The time is also logged
+ immediately if DEBUG log level is active. If the time taken
+ exceeds the given budget, log immediately with the WARN log
+ level.
+ *)
+ val timedToBudget : tag * Time.time -> (unit -> 'a) -> 'a
+
+ (** Associate the given time with the given tag, as if we had just
+ timed an invocation of it.
+ *)
val record : tag -> Time.time -> unit
+ (** Output a summary of recorded timings to the given log level.
+ *)
val summarise : Log.level -> unit
end
@@ 50,27 50,7 @@ structure Timing : TIMING = struct
val mu = implode [chr 0xCE, chr 0xBC]
fun toUsReal t = Time.toReal t * 1000000.0
-
- fun timed tag f =
- let open Log
- val start = Time.now ()
- val result = f ()
- val finish = Time.now ()
- val elapsed = Time.- (finish, start)
- val () = record tag elapsed
- val usElapsed = toUsReal elapsed
- val () = Log.debug
- (fn () =>
- ["%1: %2%3s (%4/s)",
- tag,
- N usElapsed, mu,
- if usElapsed > 0.0
- then N (1000000.0 / usElapsed)
- else "-"
- ])
- in
- result
- end
+ fun usPerSecStr u = if u > 0.0 then Log.N (1000000.0 / u) else "-"
fun summarise level =
let open Log
@@ 101,5 81,51 @@ structure Timing : TIMING = struct
(log level (fn () => ["Aggregate times in order of appearance:"]);
List.app summariseOne (rev (!recordOrder)))
end
+
+ fun timed tag f =
+ let open Log
+ val start = Time.now ()
+ val result = f ()
+ val finish = Time.now ()
+ val elapsed = Time.- (finish, start)
+ val () = record tag elapsed
+ val usElapsed = toUsReal elapsed
+ val () = Log.debug
+ (fn () =>
+ ["%1: %2%3s (%4/s)",
+ tag,
+ N usElapsed, mu, usPerSecStr usElapsed
+ ])
+ in
+ result
+ end
+
+ fun timedToBudget (tag, budget) f =
+ let open Log
+ val start = Time.now ()
+ val result = f ()
+ val finish = Time.now ()
+ val elapsed = Time.- (finish, start)
+ val () = record tag elapsed
+ val usElapsed = toUsReal elapsed
+ val () = Log.debug
+ (fn () =>
+ ["%1: %2%3s (%4/s)",
+ tag,
+ N usElapsed, mu, usPerSecStr usElapsed
+ ])
+ val usBudget = toUsReal budget
+ val () = if Time.> (elapsed, budget)
+ then Log.warn
+ (fn () =>
+ ["%1: exceeded budget of %2%3s with elapsed time of %4%5s (%6/s)",
+ tag,
+ N usBudget, mu,
+ N usElapsed, mu, usPerSecStr usElapsed
+ ])
+ else ()
+ in
+ result
+ end
end