1 /**
2 Copyright: Copyright (c) 2021, Joakim Brännström. All rights reserved.
3 License: $(LINK2 http://www.boost.org/LICENSE_1_0.txt, Boost Software License 1.0)
4 Author: Joakim Brännström (joakim.brannstrom@gmx.com)
5 
6 Utility for manually profiling of parts of a program.
7 */
8 module my.profile;
9 
10 import core.sync.mutex : Mutex;
11 import std.datetime : Duration;
12 
13 /// Execution profile result gathered from analysers.
14 private shared ProfileResults gProfile;
15 private shared Mutex gProfileMtx;
16 
17 /// Returns: the profiling results gathered for this module.
18 ProfileResults getProfileResult() @trusted {
19     gProfileMtx.lock_nothrow;
20     scope (exit)
21         gProfileMtx.unlock_nothrow();
22     auto g = cast() gProfile;
23     return new ProfileResults(g.results.dup);
24 }
25 
26 void globalSetProfile(string name, Duration time) @trusted {
27     gProfileMtx.lock_nothrow;
28     scope (exit)
29         gProfileMtx.unlock_nothrow();
30     auto g = cast() gProfile;
31     g.set(name, time);
32 }
33 
34 void globalAddProfile(string name, Duration time) @trusted {
35     gProfileMtx.lock_nothrow;
36     scope (exit)
37         gProfileMtx.unlock_nothrow();
38     auto g = cast() gProfile;
39     g.add(name, time);
40 }
41 
42 shared static this() {
43     gProfileMtx = new shared Mutex();
44     gProfile = cast(shared) new ProfileResults;
45 }
46 
47 @safe:
48 
49 /** Wall time profile of a task.
50  *
51  * If no results collector is specified the result is stored in the global
52  * collector.
53  */
54 struct Profile {
55     import std.datetime.stopwatch : StopWatch;
56 
57     enum Op {
58         add,
59         set
60     }
61 
62     string name;
63     StopWatch sw;
64     ProfileResults saveTo;
65     Op op;
66 
67     this(T)(T name, Op op, ProfileResults saveTo = null) @safe nothrow {
68         static if (is(T == string)) {
69             this.name = name;
70         } else {
71             try {
72                 this.name = name.to!string;
73             } catch (Exception e) {
74                 this.name = T.stringof;
75             }
76         }
77         this.saveTo = saveTo;
78         this.op = op;
79         sw.start;
80     }
81 
82     ~this() @safe nothrow {
83         // uninitialized
84         if (name.length == 0)
85             return;
86 
87         try {
88             sw.stop;
89             if (saveTo is null) {
90                 final switch (op) {
91                 case Op.set:
92                     globalSetProfile(name, sw.peek);
93                     break;
94                 case Op.add:
95                     globalAddProfile(name, sw.peek);
96                     break;
97                 }
98             } else {
99                 saveTo.add(name, sw.peek);
100             }
101         } catch (Exception e) {
102         }
103     }
104 }
105 
106 Profile profileSet(string name, ProfileResults saveTo = null) {
107     return Profile(name, Profile.Op.set, saveTo);
108 }
109 
110 Profile profileAdd(string name, ProfileResults saveTo = null) {
111     return Profile(name, Profile.Op.add, saveTo);
112 }
113 
114 /** Collect profiling results.
115  */
116 class ProfileResults {
117     import std.algorithm : sum, map, sort;
118     import std.array : array, appender;
119 
120     struct Result {
121         string name;
122         Duration time;
123         double ratio;
124     }
125 
126     /// The profiling for the same name is accumulated.
127     Duration[string] results;
128 
129     this() {
130     }
131 
132     this(typeof(results) results) {
133         this.results = results;
134     }
135 
136     /// Add `time` to `name`.
137     void add(string name, Duration time) {
138         results.update(name, () => time, (ref Duration a) { a += time; });
139     }
140 
141     /// Set `name` to `time`.
142     void set(string name, Duration time) {
143         results.update(name, () => time, (ref Duration a) { a = time; });
144     }
145 
146     /// Returns: the total wall time.
147     Duration totalTime() const {
148         return results.byValue.sum(Duration.zero);
149     }
150 
151     /// Returns;
152     Result[] toRows() const {
153         auto app = appender!(Result[])();
154         const double total = totalTime.total!"nsecs";
155 
156         foreach (a; results.byKeyValue.array.sort!((a, b) => a.value < b.value)) {
157             Result row;
158             row.name = a.key;
159             row.time = a.value;
160             row.ratio = cast(double) a.value.total!"nsecs" / total;
161             app.put(row);
162         }
163 
164         return app.data;
165     }
166 
167     /**
168      *
169      * This is an example from clang-tidy for how it could be reported to the user.
170      * For now it is *just* reported as it is running.
171      *
172      * ===-------------------------------------------------------------------------===
173      *                           clang-tidy checks profiling
174      * ===-------------------------------------------------------------------------===
175      *   Total Execution Time: 0.0021 seconds (0.0021 wall clock)
176      *
177      *    ---User Time---   --System Time--   --User+System--   ---Wall Time---  --- Name ---
178      *    0.0000 (  0.1%)   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.1%)  readability-misplaced-array-index
179      *    0.0000 (  0.2%)   0.0000 (  0.0%)   0.0000 (  0.1%)   0.0000 (  0.1%)  abseil-duration-division
180      *    0.0012 (100.0%)   0.0009 (100.0%)   0.0021 (100.0%)   0.0021 (100.0%)  Total
181      */
182     override string toString() const {
183         import std.algorithm : maxElement;
184         import std.format : format, formattedWrite;
185         import std.math : log10;
186 
187         const sec = 1000000000.0;
188         // 16 is the number of letters after the dot in "0.0000 (100.1%)" + 1 empty whitespace.
189         const wallMaxLen = cast(int) results.byValue.map!(a => a.total!"seconds")
190             .maxElement(1).log10 + 15;
191 
192         auto app = appender!string;
193         formattedWrite(app,
194                 "===-------------------------------------------------------------------------===\n");
195         formattedWrite(app, "                                 profiling\n");
196         formattedWrite(app,
197                 "===-------------------------------------------------------------------------===\n");
198         formattedWrite(app, "Total execution time: %.4f seconds\n\n",
199                 cast(double) totalTime.total!"nsecs" / sec);
200         formattedWrite(app, "---Wall Time--- ---Name---\n");
201 
202         void print(string name, Duration time, double ratio) {
203             auto wt = format!"%.4f (%.1f%%)"(cast(double) time.total!"nsecs" / sec, ratio * 100.0);
204             formattedWrite(app, "%-*s %s\n", wallMaxLen, wt, name);
205         }
206 
207         foreach (r; toRows) {
208             print(r.name, r.time, r.ratio);
209         }
210 
211         return app.data;
212     }
213 }
214 
215 @("shall accumulate profiling results")
216 unittest {
217     import std.conv : to;
218     import std.stdio : writeln;
219 
220     auto pc = new ProfileResults;
221 
222     foreach (_; 0 .. 10)
223         auto p = profileSet("a", pc);
224     assert(pc.toRows.length == 1);
225 
226     foreach (i; 0 .. 10)
227         auto p = profileAdd("a" ~ i.to!string, pc);
228     assert(pc.toRows.length == 11);
229 
230     writeln(pc);
231 }