View Javadoc
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-2024 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 String; 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 String; name
68       * @param nanoTime Long; 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 String; 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 String; name
95       * @param nanoTime Long; 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 String; name
105      * @param start boolean; start command; if true; an entry may be added to the LINES map
106      * @return ProfileInfo; 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 String; name that was used in <code>start</code> and <code>end</code> calls.
211      * @return String; 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 long; 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-2024 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 String; 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 long; 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 long; 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 String; user given id
372          */
373         public String getName()
374         {
375             return this.name;
376         }
377 
378         /**
379          * Returns total profiling time [s].
380          * @return double; 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 double; 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 int; 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 double; 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 }