1 package org.djutils.profile;
2
3 import java.util.Collections;
4 import java.util.LinkedHashMap;
5 import java.util.Map;
6 import java.util.Map.Entry;
7 import java.util.TreeMap;
8
9 import org.djutils.exceptions.Throw;
10
11 /**
12 * Utility class to profile code execution times. <br>
13 * Insert a call to one of the <code>start</code> methods at the start of each method (or part thereof) that must be timed and a
14 * call to one of the <code>end</code> methods at the end of the part to profile or right before every return statement of each
15 * of those methods. <br>
16 * The collected statistics information can be retrieved with the <code>statistics</code> method. <br>
17 * To output statistics at (somewhat) regular intervals call <code>print</code> method often. The default interval is 1 second;
18 * this can be changed by calling the <code>setPrintInterval method</code>.
19 * <p>
20 * Copyright (c) 2013-2022 Delft University of Technology, PO Box 5, 2600 AA, Delft, the Netherlands. All rights reserved. <br>
21 * BSD-style license. See <a href="https://djutils.org/docs/current/djutils/licenses.html">DJUTILS License</a>.
22 * <p>
23 * @version $Revision$, $LastChangedDate$, by $Author$, initial version 27 jan. 2018 <br>
24 * @author <a href="http://www.tbm.tudelft.nl/averbraeck">Alexander Verbraeck</a>
25 * @author <a href="http://www.tudelft.nl/pknoppers">Peter Knoppers</a>
26 * @author <a href="http://www.transport.citg.tudelft.nl">Wouter Schakel</a>
27 */
28 public final class Profile
29 {
30
31 /** Map containing ProfileInfo objects. */
32 private static final Map<String, ProfileInfo> INFOS = new LinkedHashMap<>();
33
34 /** Map containing most recent part id's as line numbers. */
35 private static final Map<String, String> LINES = new LinkedHashMap<>();
36
37 /** Minimum print interval [ms]; during this time after a print, prints are suppressed. */
38 private static long printInterval = 1000;
39
40 /** Time of last print. */
41 private static long lastPrint = 0;
42
43 /** Private constructor. */
44 private Profile()
45 {
46 // Do not instantiate
47 }
48
49 /**
50 * Starts timing on the calling class and method, specified by line number.
51 */
52 public static void start()
53 {
54 start0(null, System.nanoTime());
55 }
56
57 /**
58 * Starts timing on the calling class and method, specified by given name.
59 * @param name String; name
60 */
61 public static void start(final String name)
62 {
63 start0(name, System.nanoTime());
64 }
65
66 /**
67 * Forwarding method used for consistent stack trace filtering.
68 * @param name String; name
69 * @param nanoTime Long; time obtained by entrance method
70 */
71 private static void start0(final String name, final Long nanoTime)
72 {
73 getProfileInfo(name, true).start(nanoTime);
74 }
75
76 /**
77 * Ends timing on the calling class and method, specified by line number (of the start command).
78 */
79 public static void end()
80 {
81 end0(null, System.nanoTime());
82 }
83
84 /**
85 * Ends timing on the calling class and method, specified by given name.
86 * @param name String; name
87 */
88 public static void end(final String name)
89 {
90 end0(name, System.nanoTime());
91 }
92
93 /**
94 * Forwarding method used for consistent stack trace filtering.
95 * @param name String; name
96 * @param nanoTime Long; time obtained by entrance method
97 */
98 private static void end0(final String name, final Long nanoTime)
99 {
100 getProfileInfo(name, false).end(nanoTime);
101 }
102
103 /**
104 * Returns the profile info, which is created if none was present.
105 * @param name String; name
106 * @param start boolean; start command; if true; an entry may be added to the LINES map
107 * @return ProfileInfo; applicable info
108 */
109 private static ProfileInfo getProfileInfo(final String name, final boolean start)
110 {
111 StackTraceElement element = Thread.currentThread().getStackTrace()[4];
112 String classMethodId = element.getClassName() + ":" + element.getMethodName();
113 String partId;
114 if (name == null)
115 {
116 if (start)
117 {
118 partId = ":" + String.valueOf(element.getLineNumber());
119 LINES.put(classMethodId, partId);
120 }
121 else
122 {
123 partId = LINES.get(classMethodId);
124 }
125 }
126 else
127 {
128 partId = ":" + name;
129 }
130 classMethodId += partId;
131
132 ProfileInfo info = INFOS.get(classMethodId);
133 if (info == null)
134 {
135 info = new ProfileInfo(name);
136 INFOS.put(classMethodId, info);
137 }
138 return info;
139 }
140
141 /**
142 * Returns a formatted string of a table with statistics.
143 * @return String formatted string of a table with statistics
144 */
145 public static String statistics()
146 {
147 // gather totals information and sort
148 double sum = 0;
149 int maxInvocations = 0;
150 int maxNameLength = 4;
151 Map<Double, Entry<String, ProfileInfo>> sorted = new TreeMap<>(Collections.reverseOrder());
152 for (Entry<String, ProfileInfo> entry : INFOS.entrySet())
153 {
154 String id = entry.getKey();
155 ProfileInfo info = INFOS.get(id);
156 sorted.put(info.getTotal(), entry);
157 sum += info.getTotal();
158 maxInvocations = maxInvocations > info.getInvocations() ? maxInvocations : info.getInvocations();
159 int nameLength = (info.getName() == null ? id : info.getName()).length();
160 maxNameLength = maxNameLength > nameLength ? maxNameLength : nameLength;
161 }
162 int lengthInvoke = String.valueOf(maxInvocations).length();
163 lengthInvoke = lengthInvoke > 6 ? lengthInvoke : 6;
164 String invokeHeaderFormat = String.format("%%%d.%ds", lengthInvoke, lengthInvoke);
165 String invokeLineFormat = String.format("%%%ds", lengthInvoke);
166 String nameHeaderFormat = String.format("%%%d.%ds", maxNameLength, maxNameLength);
167 String nameLineFormat = String.format("%%%ds", maxNameLength);
168 String line = new String(new char[80 + lengthInvoke + maxNameLength]).replace("\0", "-"); // -------------- line
169
170 // Header
171 StringBuilder builder = new StringBuilder();
172 builder.append("-").append(line).append("-\n");
173 builder.append(String.format("| %7.7s | ", "Perc."));
174 builder.append(String.format(invokeHeaderFormat, "#Calls"));
175 builder.append(String.format(" | %10.10s | %10.10s | %10.10s | %10.10s | %10.10s | ", "TotTime", "MinTime", "MaxTime",
176 "AvgTime", "StdTime"));
177 builder.append(String.format(nameHeaderFormat, "Name")).append(" |\n");
178 builder.append("|").append(line).append("|\n");
179
180 // Statistics; one line for each profiled method
181 for (Entry<String, ProfileInfo> entry : sorted.values())
182 {
183 String id = entry.getKey();
184 ProfileInfo info = entry.getValue();
185 if (info.getInvocations() > 0)
186 {
187 double perc = 100.0 * info.getTotal() / sum;
188 builder.append(String.format("| %6.2f%% | ", perc));
189 builder.append(String.format(invokeLineFormat, info.getInvocations()));
190 builder.append(String.format(" | %9.4fs | %9.6fs | %9.6fs | %9.6fs | ", info.getTotal(), info.getMin(),
191 info.getMax(), info.getMean()));
192 // Standard deviation
193 if (info.getInvocations() > 1)
194 {
195 builder.append(String.format("%9.6fs", info.getStandardDeviation()));
196 }
197 else
198 {
199 builder.append(" ");
200 }
201 // Name of the profiled method
202 builder.append(" | ").append(String.format(nameLineFormat, info.getName() == null ? id : info.getName()))
203 .append(" |\n");
204 }
205 }
206 return builder.append("-").append(line).append("-\n").toString();
207 }
208
209 /**
210 * Return statistics of one sampler (which must have identified itself with a name).
211 * @param name String; name that was used in <code>start</code> and <code>end</code> calls.
212 * @return String; the results, or null if no information was gathered under that name
213 */
214 public static String statistics(final String name)
215 {
216 Throw.whenNull(name, "name may not be null");
217 for (ProfileInfo result : INFOS.values())
218 {
219 if (null == result)
220 {
221 return null;
222 }
223 if (name.equals(result.getName()))
224 {
225 return result.toString();
226 }
227 }
228 return null;
229 }
230
231 /**
232 * Prints profiling output to the console once every 1s or longer, or according to the time set in
233 * {@code setPrintInterval()}. This method needs to be called frequently, and will only print again after the print interval
234 * has elapsed. If execution time between two calls to this method is longer than the print interval, this method prints
235 * directly.
236 */
237 public static void print()
238 {
239 long t = System.currentTimeMillis();
240 if (t - lastPrint > printInterval)
241 {
242 lastPrint = t;
243 System.out.print(statistics());
244 }
245 }
246
247 /**
248 * Sets a print interval.
249 * @param printInterval long; print interval in ms
250 */
251 public static void setPrintInterval(final long printInterval)
252 {
253 Profile.printInterval = printInterval;
254 }
255
256 /**
257 * Remove all collected statistics. Does not reset the print interval, or the time of last print.
258 */
259 public static void clear()
260 {
261 INFOS.clear();
262 LINES.clear();
263 }
264
265 /**
266 * Reset the collected running time values of all observed methods and method fragments.
267 */
268 public static void reset()
269 {
270 for (ProfileInfo pi : INFOS.values())
271 {
272 pi.reset();
273 }
274 }
275
276 /**
277 * Contains info per profiling part.
278 * <p>
279 * Copyright (c) 2013-2022 Delft University of Technology, PO Box 5, 2600 AA, Delft, the Netherlands. All rights reserved.
280 * <br>
281 * BSD-style license. See <a href="https://djutils.org/docs/current/djutils/licenses.html">DJUTILS License</a>.
282 * <p>
283 * @version $Revision$, $LastChangedDate$, by $Author$, initial version 27 jan. 2018 <br>
284 * @author <a href="http://www.tbm.tudelft.nl/averbraeck">Alexander Verbraeck</a>
285 * @author <a href="http://www.tudelft.nl/pknoppers">Peter Knoppers</a>
286 * @author <a href="http://www.transport.citg.tudelft.nl">Wouter Schakel</a>
287 */
288 private static class ProfileInfo
289 {
290 /** Conversion factor to convert the timer steps (nanoseconds) to the SI unit for duration (seconds). */
291 private static final double NANOSECONDSPERSECOND = 1000000000.0;
292
293 /** User given name. */
294 private final String name;
295
296 /** Start time in nanoseconds (since start time of JVM) of recording. */
297 private Long start = null;
298
299 /** Total time in nanoseconds of profiling. */
300 private long total;
301
302 /** Total of instance times in nanoseconds squared. */
303 private long totalSquared;
304
305 /** Minimum execution time in nanoseconds. */
306 private long minTime;
307
308 /** Maximum execution time in nanoseconds. */
309 private long maxTime;
310
311 /** Number of invocations. */
312 private int invocations;
313
314 /**
315 * Constructor.
316 * @param name String; user given name
317 */
318 ProfileInfo(final String name)
319 {
320 this.name = name;
321 }
322
323 /**
324 * Reset all collected running time values of this ProfileInfo object.
325 */
326 public void reset()
327 {
328 this.start = null;
329 this.total = 0;
330 this.totalSquared = 0;
331 this.minTime = 0;
332 this.maxTime = 0;
333 this.invocations = 0;
334 }
335
336 /**
337 * Sets the start time .
338 * @param startTime long; start time in nanoseconds
339 */
340 public void start(final long startTime)
341 {
342 Throw.when(this.start != null, IllegalStateException.class,
343 "Can not start profiling because it is already running.");
344 this.start = startTime;
345 }
346
347 /**
348 * Adds to total profiling time.
349 * @param endTime long; end time in nanoseconds
350 */
351 public void end(final long endTime)
352 {
353 Throw.when(this.start == null, IllegalStateException.class, "Can not end profiling because it is not running.");
354 long duration = endTime - this.start;
355 this.total += duration;
356 this.totalSquared += duration * duration;
357 if (this.invocations == 0)
358 {
359 this.minTime = duration;
360 this.maxTime = duration;
361 }
362 else
363 {
364 this.minTime = this.minTime < duration ? this.minTime : duration;
365 this.maxTime = this.maxTime > duration ? this.maxTime : duration;
366 }
367 this.invocations++;
368 this.start = null;
369 }
370
371 /**
372 * Returns the user given id.
373 * @return String; user given id
374 */
375 public String getName()
376 {
377 return this.name;
378 }
379
380 /**
381 * Returns total profiling time [s].
382 * @return double; total profiling time [s]
383 */
384 public double getTotal()
385 {
386 return this.total / NANOSECONDSPERSECOND;
387 }
388
389 /**
390 * Returns profiling time deviation [s].
391 * @return double; profiling time deviation [s], or NaN if only one invocation was logged
392 */
393 public double getStandardDeviation()
394 {
395 if (this.invocations < 2)
396 {
397 return Double.NaN;
398 }
399 double squared = this.totalSquared - this.total * this.total / this.invocations;
400 return Math.sqrt(squared / (this.invocations - 1)) / NANOSECONDSPERSECOND;
401 }
402
403 /**
404 * Returns the number of invocations.
405 * @return int; number of invocations
406 */
407 public int getInvocations()
408 {
409 return this.invocations;
410 }
411
412 /**
413 * Returns the mean execution time [s].
414 * @return double; mean execution time [s]
415 */
416 public double getMean()
417 {
418 return getTotal() / getInvocations();
419 }
420
421 /**
422 * Returns the minimum execution time [s].
423 * @return minimum execution time [s]
424 */
425 public double getMin()
426 {
427 return this.minTime / NANOSECONDSPERSECOND;
428 }
429
430 /**
431 * Returns the maximum execution time [s].
432 * @return maximum execution time [s]
433 */
434 public double getMax()
435 {
436 return this.maxTime / NANOSECONDSPERSECOND;
437 }
438
439 /** {@inheritDoc} */
440 @Override
441 public String toString()
442 {
443 return "ProfileInfo [name=" + this.name + ", start=" + this.start + ", total=" + this.total + ", totalSquared="
444 + this.totalSquared + ", minTime=" + this.minTime + ", maxTime=" + this.maxTime + ", invocations="
445 + this.invocations + "]";
446 }
447
448 }
449
450 }