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