src/Pure/General/timing.ML
author wenzelm
Sun, 20 Mar 2011 21:28:11 +0100
changeset 42012 2c3fe3cbebae
parent 40393 2bb7ec08574a
child 42013 1694cc477045
permissions -rw-r--r--
structure Timing: covers former start_timing/end_timing and Output.timeit etc; explicit Timing.message function; eliminated Output.timing flag, cf. Toplevel.timing; tuned;
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
40393
2bb7ec08574a somewhat more uniform timing in ML vs. Scala;
wenzelm
parents: 40391
diff changeset
     1
(*  Title:      Pure/General/timing.ML
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
     2
    Author:     Makarius
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
     3
40336
wenzelm
parents: 40300
diff changeset
     4
Basic support for time measurement.
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
     5
*)
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
     6
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
     7
signature BASIC_TIMING =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
     8
sig
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
     9
  val cond_timeit: bool -> string -> (unit -> 'a) -> 'a
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    10
  val timeit: (unit -> 'a) -> 'a
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    11
  val timeap: ('a -> 'b) -> 'a -> 'b
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    12
  val timeap_msg: string -> ('a -> 'b) -> 'a -> 'b
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    13
end
40300
d4487353b3a0 added convenience operation seconds: real -> time;
wenzelm
parents: 32935
diff changeset
    14
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    15
signature TIMING =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    16
sig
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    17
  include BASIC_TIMING
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    18
  type timing = {elapsed: Time.time, cpu: Time.time, gc: Time.time}
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    19
  type start
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    20
  val start: unit -> start
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    21
  val result: start -> timing
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    22
  val message: timing -> string
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    23
end
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    24
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    25
structure Timing: TIMING =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    26
struct
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    27
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    28
(* timer control *)
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    29
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    30
type timing = {elapsed: Time.time, cpu: Time.time, gc: Time.time};
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    31
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    32
abstype start = Start of
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    33
  Timer.real_timer * Time.time * Timer.cpu_timer *
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    34
    {gc: {sys: Time.time, usr: Time.time}, nongc: {sys: Time.time, usr: Time.time}}
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    35
with
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    36
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    37
fun start () =
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    38
  let
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    39
    val real_timer = Timer.startRealTimer ();
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    40
    val real_time = Timer.checkRealTimer real_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    41
    val cpu_timer = Timer.startCPUTimer ();
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    42
    val cpu_times = Timer.checkCPUTimes cpu_timer;
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    43
  in Start (real_timer, real_time, cpu_timer, cpu_times) end;
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    44
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    45
fun result (Start (real_timer, real_time, cpu_timer, cpu_times)) =
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    46
  let
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    47
    val real_time2 = Timer.checkRealTimer real_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    48
    val {nongc = {sys, usr}, gc = {sys = gc_sys, usr = gc_usr}} = cpu_times;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    49
    val {nongc = {sys = sys2, usr = usr2}, gc = {sys = gc_sys2, usr = gc_usr2}} =
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    50
      Timer.checkCPUTimes cpu_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    51
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    52
    open Time;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    53
    val elapsed = real_time2 - real_time;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    54
    val gc = gc_usr2 - gc_usr + gc_sys2 - gc_sys;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    55
    val cpu = usr2 - usr + sys2 - sys + gc;
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    56
  in {elapsed = elapsed, cpu = cpu, gc = gc} end;
32935
2218b970325a show direct GC time (which is included in CPU time);
wenzelm
parents: 31757
diff changeset
    57
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    58
end;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    59
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    60
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    61
(* timing messages *)
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    62
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    63
fun message {elapsed, cpu, gc} =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    64
  Time.toString elapsed ^ "s elapsed time, " ^
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    65
  Time.toString cpu ^ "s cpu time, " ^
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    66
  Time.toString gc ^ "s GC time" handle Time.Time => "";
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    67
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    68
fun cond_timeit enabled msg e =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    69
  if enabled then
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    70
    let
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    71
      val timing_start = start ();
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    72
      val res = Exn.capture e ();
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    73
      val end_msg = message (result timing_start);
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    74
      val _ = warning (if msg = "" then end_msg else msg ^ "\n" ^ end_msg);
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    75
    in Exn.release res end
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    76
  else e ();
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    77
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    78
fun timeit e = cond_timeit true "" e;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    79
fun timeap f x = timeit (fn () => f x);
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    80
fun timeap_msg msg f x = cond_timeit true msg (fn () => f x);
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    81
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    82
end;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    83
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    84
structure Basic_Timing: BASIC_TIMING = Timing;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    85
open Basic_Timing;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    86