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 }