author | wenzelm |
Wed, 12 Mar 2025 11:39:00 +0100 | |
changeset 82265 | 4b875a4c83b0 |
parent 82092 | 93195437fdee |
permissions | -rw-r--r-- |
40393 | 1 |
(* Title: Pure/General/timing.ML |
31686 | 2 |
Author: Makarius |
3 |
||
74158 | 4 |
Support for time measurement. |
31686 | 5 |
*) |
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 | 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 | 24 |
val is_relevant_time: Time.time -> bool |
44440 | 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 | 27 |
val protocol_message: string -> Position.T -> timing -> unit |
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 | 38 |
val zero: timing = {elapsed = Time.zeroTime, cpu = Time.zeroTime, gc = Time.zeroTime}; |
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 | 49 |
let |
50 |
val real_timer = Timer.startRealTimer (); |
|
51 |
val real_time = Timer.checkRealTimer real_timer; |
|
52 |
val cpu_timer = Timer.startCPUTimer (); |
|
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 | 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 | 57 |
let |
58 |
val real_time2 = Timer.checkRealTimer real_timer; |
|
59 |
val {nongc = {sys, usr}, gc = {sys = gc_sys, usr = gc_usr}} = cpu_times; |
|
60 |
val {nongc = {sys = sys2, usr = usr2}, gc = {sys = gc_sys2, usr = gc_usr2}} = |
|
61 |
Timer.checkCPUTimes cpu_timer; |
|
62 |
||
63 |
val elapsed = real_time2 - real_time; |
|
64 |
val gc = gc_usr2 - gc_usr + gc_sys2 - gc_sys; |
|
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 | 79 |
val min_time = Time.fromMilliseconds 1; |
80 |
||
62826 | 81 |
fun is_relevant_time time = time >= min_time; |
51228 | 82 |
|
42819 | 83 |
fun is_relevant {elapsed, cpu, gc} = |
51228 | 84 |
is_relevant_time elapsed orelse |
85 |
is_relevant_time cpu orelse |
|
86 |
is_relevant_time gc; |
|
42819 | 87 |
|
44440 | 88 |
fun message {elapsed, cpu, gc} = |
82092 | 89 |
Time.message elapsed ^ " elapsed time, " ^ |
90 |
Time.message cpu ^ " cpu time, " ^ |
|
91 |
Time.message gc ^ " GC time" handle Time.Time => ""; |
|
44440 | 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 | 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 | 100 |
in warning (if msg = "" then end_msg else msg ^ "\n" ^ end_msg) end |
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 | 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 | 111 |
let val props = Markup.command_timing :: (Markup.nameN, name) :: Position.properties_of pos |
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 | 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 | 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; |