Simple timing profiler for functional languages

3
votes

I needed a simple timing profiler to estimate the runtime of some parts of my program (written in OCaml, but I believe this could apply to other functional languages), and I couldn't find a very simple solution, similar to what one would code in an imperative language, using functions such as timer.start/timer.stop. So I tried one using lazy evaluation, and it works quite well for what I need, however I didn't find any references to this method, so I wonder it the approach is flawed or if there is a simpler solution.

So, the question is: do you know about similar implementations for functional languages (especially OCaml)? If so, please indicate them to me, I'd like to borrow some of their ideas to improve my "poorer man's profiler" (I've seen this question but it didn't help me much). From what I've seen, GHC already has a way to collect timing information, so it's probably not an issue for Haskell.

By the way, I tried doing timing profiling as indicated in the OCaml manual (17.4), but it was too "low-level" for what I needed: it gives lots of information at the C function level, which make it harder to evaluate precisely which part of the OCaml code is the culprit.

Below follows my implementation in OCaml (note that I need to add the "lazy" expression everytime I want to measure the time, but at the same time I can finely control how much information I need).

open Unix (* for the timers *)

(** 'timers' associates keys (strings) to time counters, 
   to allow for multiple simultaneous measurements. *)
let timers : (string, (float * float)) Hashtbl.t = Hashtbl.create 1

(** starts the timer associated with key <name> *)
let timer_start (name : string) : unit =
  let now = Unix.times () in
  Hashtbl.replace timers name (now.tms_utime, now.tms_stime)

(** Returns time elapsed between the corresponding call to 
   timer_start and this call *)
let timer_stop (name : string) : float =
  try
    let now = Unix.times () in
    let t = Hashtbl.find timers name in
    (now.tms_utime -. fst t) +. (now.tms_stime -. snd t)
  with
    Not_found -> 0.0

(** Wrapper for the timer function using lazy evaluation *)
let time (s : string) (e : 'a Lazy.t) : 'a =
  timer_start s;
  let a = Lazy.force e in
  let t2 = timer_stop s in
  (* outputs timing information *)
  Printf.printf "TIMER,%s,%f\n" s t2; a


(** Example *)
let rec fibo n = 
  match n with
    | 0 -> 1
    | 1 -> 1
    | n' -> fibo (n - 1) + fibo (n - 2)

let main =
  let f = time "fibo" (lazy (fibo 42)) in
  Printf.printf "f = %d\n" f
2
profilingocaml
This looks good to me (the archetypal poor man). I've written some systems like this and they've worked for me. You don't really need to use the lazy facility as far as I can see. Seems like you could just pass a thunk (fun () -> expr), which might avoid allocating then throwing away a little extra structure for the lazy value. (AFAIK a lazy value is equivalent to a lambda and a box.) But lazy expressions are notationally a little suaver I guess. – Jeffrey Scofield
The thunk is indeed the best choice, I originally wanted to avoid it but then when I had to use the somewhat ugly "lazy" wrapper, I didn't consider going back to the previous solution... thanks! – anol

2 Answers

2
votes

Unix.times measures CPU time, not wall-clock time. So this is suitable only for computational code that spends all of its time in CPU. And BTW hashtbl is not needed, even for multiple simultaneous measurements, just return the start time in timer_start and substract it in timer_stop.

1
votes

Merging the ideas from @Jeffrey_Scofield and @ygrek, the "poorest man's timing profiler" is indeed so simple it would barely require mention at all, which would explain why I hadn't found it. So I've merged their answers and produced a much simpler version:

open Unix (* for the timers *)

(* Wrapper for the timer function using a "unit -> 'a" thunk *)
let time (s : string) (e : unit -> 'a) : 'a =
  let tstart = Unix.times () in
  let a = e () in
  let tend = Unix.times () in
  let delta = (tend.tms_utime -. tstart.tms_utime) +. 
              (tend.tms_stime -. tstart.tms_stime) in
  (* outputs timing information *)
  Printf.printf "TIMER,%s,%f\n" s delta; a

(* Example *)
let rec fibo n = 
  match n with
    | 0 -> 1
    | 1 -> 1
    | n' -> fibo (n - 1) + fibo (n - 2)

let main =
  let f = time "fibo" (fun () -> fibo 42) in
  Printf.printf "f = %d\n" f