src/Pure/General/timing.ML
author wenzelm
Wed, 12 Mar 2025 11:39:00 +0100
changeset 82265 4b875a4c83b0
parent 82092 93195437fdee
permissions -rw-r--r--
update for release;
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
74158
wenzelm
parents: 67932
diff changeset
     4
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}
82086
e0edf30885ef tuned signature: more explicit operations;
wenzelm
parents: 78705
diff changeset
    19
  val zero: timing
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    20
  type start
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    21
  val start: unit -> start
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    22
  val result: start -> timing
42013
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    23
  val timing: ('a -> 'b) -> 'a -> timing * 'b
51228
dff3471dd8bc more tight representation of command timing;
wenzelm
parents: 51217
diff changeset
    24
  val is_relevant_time: Time.time -> bool
44440
aa2abd81f460 ignore irrelevant timings;
wenzelm
parents: 42819
diff changeset
    25
  val is_relevant: timing -> bool
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    26
  val message: timing -> string
67932
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
    27
  val protocol_message: string -> Position.T -> timing -> unit
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
    28
  val protocol: string -> Position.T -> ('a -> 'b) -> 'a -> 'b
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    29
end
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    30
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    31
structure Timing: TIMING =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    32
struct
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    33
51217
65ab2c4f4c32 support for prescient timing information within command transactions;
wenzelm
parents: 50781
diff changeset
    34
(* type timing *)
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    35
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    36
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
    37
82086
e0edf30885ef tuned signature: more explicit operations;
wenzelm
parents: 78705
diff changeset
    38
val zero: timing = {elapsed = Time.zeroTime, cpu = Time.zeroTime, gc = Time.zeroTime};
e0edf30885ef tuned signature: more explicit operations;
wenzelm
parents: 78705
diff changeset
    39
51217
65ab2c4f4c32 support for prescient timing information within command transactions;
wenzelm
parents: 50781
diff changeset
    40
65ab2c4f4c32 support for prescient timing information within command transactions;
wenzelm
parents: 50781
diff changeset
    41
(* timer control *)
65ab2c4f4c32 support for prescient timing information within command transactions;
wenzelm
parents: 50781
diff changeset
    42
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    43
abstype start = Start of
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    44
  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
    45
    {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
    46
with
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    47
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    48
fun start () =
31686
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    49
  let
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    50
    val real_timer = Timer.startRealTimer ();
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    51
    val real_time = Timer.checkRealTimer real_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    52
    val cpu_timer = Timer.startCPUTimer ();
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    53
    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
    54
  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
    55
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    56
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
    57
  let
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    58
    val real_time2 = Timer.checkRealTimer real_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    59
    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
    60
    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
    61
      Timer.checkCPUTimes cpu_timer;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    62
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    63
    val elapsed = real_time2 - real_time;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    64
    val gc = gc_usr2 - gc_usr + gc_sys2 - gc_sys;
e54ae15335a1 more detailed start_timing/end_timing (in timing.ML);
wenzelm
parents:
diff changeset
    65
    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
    66
  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
    67
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    68
end;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    69
42013
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    70
fun timing f x =
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    71
  let
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    72
    val start = start ();
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    73
    val y = f x;
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    74
  in (result start, y) end;
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
    75
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    76
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    77
(* timing messages *)
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    78
42819
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
    79
val min_time = Time.fromMilliseconds 1;
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
    80
62826
eb94e570c1a4 prefer infix operations;
wenzelm
parents: 59149
diff changeset
    81
fun is_relevant_time time = time >= min_time;
51228
dff3471dd8bc more tight representation of command timing;
wenzelm
parents: 51217
diff changeset
    82
42819
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
    83
fun is_relevant {elapsed, cpu, gc} =
51228
dff3471dd8bc more tight representation of command timing;
wenzelm
parents: 51217
diff changeset
    84
  is_relevant_time elapsed orelse
dff3471dd8bc more tight representation of command timing;
wenzelm
parents: 51217
diff changeset
    85
  is_relevant_time cpu orelse
dff3471dd8bc more tight representation of command timing;
wenzelm
parents: 51217
diff changeset
    86
  is_relevant_time gc;
42819
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
    87
44440
aa2abd81f460 ignore irrelevant timings;
wenzelm
parents: 42819
diff changeset
    88
fun message {elapsed, cpu, gc} =
82092
93195437fdee clarified signature;
wenzelm
parents: 82086
diff changeset
    89
  Time.message elapsed ^ " elapsed time, " ^
93195437fdee clarified signature;
wenzelm
parents: 82086
diff changeset
    90
  Time.message cpu ^ " cpu time, " ^
93195437fdee clarified signature;
wenzelm
parents: 82086
diff changeset
    91
  Time.message gc ^ " GC time" handle Time.Time => "";
44440
aa2abd81f460 ignore irrelevant timings;
wenzelm
parents: 42819
diff changeset
    92
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    93
fun cond_timeit enabled msg e =
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    94
  if enabled then
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
    95
    let
78705
fde0b195cb7d clarified signature: avoid association with potentially dangerous Exn.capture;
wenzelm
parents: 74158
diff changeset
    96
      val (t, result) = timing (Exn.result e) ();
42819
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
    97
      val _ =
51606
2843cc095a57 additional timing status for implicitly forked terminal proofs -- proper accounting for interactive Timing dockable etc.;
wenzelm
parents: 51228
diff changeset
    98
        if is_relevant t then
2843cc095a57 additional timing status for implicitly forked terminal proofs -- proper accounting for interactive Timing dockable etc.;
wenzelm
parents: 51228
diff changeset
    99
          let val end_msg = message t
42819
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
   100
          in warning (if msg = "" then end_msg else msg ^ "\n" ^ end_msg) end
cce39fdaad7b only show relevant timing;
wenzelm
parents: 42042
diff changeset
   101
        else ();
42013
1694cc477045 pure Timing.timing, without any exception handling;
wenzelm
parents: 42012
diff changeset
   102
    in Exn.release result end
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   103
  else e ();
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   104
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   105
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
   106
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
   107
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
   108
67932
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
   109
fun protocol_message name pos t =
59149
0070053570c4 suppress irrelevant timing messages (the majority);
wenzelm
parents: 56333
diff changeset
   110
  if is_relevant t then
67932
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
   111
    let val props = Markup.command_timing :: (Markup.nameN, name) :: Position.properties_of pos
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
   112
    in Output.try_protocol_message (props @ Markup.timing_properties t) [] end
59149
0070053570c4 suppress irrelevant timing messages (the majority);
wenzelm
parents: 56333
diff changeset
   113
  else ();
51662
3391a493f39a just one timing protocol function, with 3 implementations: TTY/PG, PIDE/document, build;
wenzelm
parents: 51606
diff changeset
   114
67932
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
   115
fun protocol name pos f x =
51606
2843cc095a57 additional timing status for implicitly forked terminal proofs -- proper accounting for interactive Timing dockable etc.;
wenzelm
parents: 51228
diff changeset
   116
  let
78705
fde0b195cb7d clarified signature: avoid association with potentially dangerous Exn.capture;
wenzelm
parents: 74158
diff changeset
   117
    val (t, result) = timing (Exn.result f) x;
67932
04352338f7f3 clarified signature;
wenzelm
parents: 67001
diff changeset
   118
    val _ = protocol_message name pos t;
51606
2843cc095a57 additional timing status for implicitly forked terminal proofs -- proper accounting for interactive Timing dockable etc.;
wenzelm
parents: 51228
diff changeset
   119
  in Exn.release result end;
2843cc095a57 additional timing status for implicitly forked terminal proofs -- proper accounting for interactive Timing dockable etc.;
wenzelm
parents: 51228
diff changeset
   120
42012
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   121
end;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   122
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   123
structure Basic_Timing: BASIC_TIMING = Timing;
2c3fe3cbebae structure Timing: covers former start_timing/end_timing and Output.timeit etc;
wenzelm
parents: 40393
diff changeset
   124
open Basic_Timing;