| Profiler.java |
1 /*
2 * Profiler.java - A simple profiling utility
3 *
4 * Copyright (c) 2001, OntoText Lab. (http://www.ontotext.com)
5 *
6 * This file is part of GATE (see http://gate.ac.uk/), and is free
7 * software, licenced under the GNU Library General Public License,
8 * Version 2, June 1991 (in the distribution as file licence.html,
9 * and also available at http://gate.ac.uk/gate/licence.html).
10 *
11 * Atanas Kiryakov, 05/11/01
12 *
13 * $Id: Profiler.java,v 1.4 2004/06/04 17:00:09 valyt Exp $
14 */
15
16
17 package gate.util.profile;
18
19 /**
20 * This is a simple "code-internal" profiler which can be used
21 * by introducing calls to its methods (mostly, checkPoint()) in the code.
22 * It allows detection and reporting of time and memory usage
23 * between execution points as well as for the whole run. In addition allows
24 * for collection/reporting of the resources usage by categories (types of
25 * activity performed between the check point and the previous one).
26 * The results are currently just dumped to the output.
27 * <p>
28 * Important feature is the possibility of the memory usage measurment code
29 * to call the Garbage Collector following a specific strategy that allows
30 * the real memory usage to be deteceted. This feature can be switched OFF
31 * if appropriate, for example, if the *real* run-time memory usage have to
32 * be measured rather than the precise but ideallistic one provided otherwise.
33 * <p>
34 * The profiler can be switched OFF using the enable(boolean) method. In such
35 * case it ignores any calls to its checkPoint(...) method, so, basically does
36 * nothing. This feature is usefull in cases when the profiler have to be
37 * "stripped" from the code in order to allow non-disturbed execution.
38 * <p>
39 * The profiler takes care to calculate the time exlusive its footprint. It
40 * takes account for both "net" time and the absolute duration. Also in
41 * relation to the execution time measurment - it depends on the speed of the
42 * machine as well as on the other applications running in parallel.
43 */
44
45 import java.io.PrintStream;
46 import java.util.Enumeration;
47 import java.util.Hashtable;
48
49 public class Profiler {
50
51 private PrintStream m_out;
52 private boolean m_enabled = true;
53 private boolean m_garbageCollection = true;
54 /** Indicates whether just to return the string dumps (false) or also print them
55 to the std out (true)*/
56 private boolean m_doPrintToStdOut = true;
57
58 // keeps the sum of the time spend on a category of tasks
59 // the catoegries are identified via strings which are used as
60 // keys in the table. The values in the table are Long objects, millisec.
61 private Hashtable m_categorySums;
62
63 // keeps the time spend on the last task of a category
64 // the catoegries are identified via strings which are used as
65 // keys in the table. The values in the table are Long objects, millisec.
66 private Hashtable m_categoryLasts;
67
68 private Runtime m_rt;
69
70 // all the time constants below in 1/1000s
71 // the time when the profiler was intiated for the current run
72 private long m_startTime;
73 private long m_lastCheckTime, m_profilerTime, m_lastDuration;
74
75 private long m_maxMemory, m_currMemory, m_diffMemory;
76
77 public Profiler() {
78 m_rt = Runtime.getRuntime();
79 m_out = System.out;
80 }
81
82 /**
83 * Switches the profiler ON and OFF. When OFF all the methods do nothing
84 */
85 public void enable(boolean isEnabled) {
86 m_enabled = isEnabled;
87 } // enable
88
89 /**
90 * Answers is the profiler switched ON or OFF. When OFF all the methods do
91 * nothing
92 */
93 public boolean isEnabled() {
94 return m_enabled;
95 }
96
97 /**
98 * Tell's the profiler whether to call the garbage collector when detecting
99 * memory usage or not. If switched ON the GC is called following a
100 * specific strategy as many time as needed so to collect all the memory
101 * that can be collected. This makes the profiling slower and also does not
102 * correctly account for the really memory usage of the applicaton when
103 * run without the profiler. On the other hand, with garbage collection, it
104 * is easier to detecet the amount of memory really necessary for the
105 * application.
106 */
107 public void enableGCCalling(boolean collect) {
108 m_garbageCollection = collect;
109 }
110
111 /**
112 * @see #enableGCCalling(boolean)
113 */
114 public boolean isGCCallingEnabled() {
115 return m_garbageCollection;
116 }
117
118
119 /**
120 * Returns the time spend by the profiler during the last run. It is the
121 * case that
122 * net_run_time = run_duration - profiler_time
123 */
124 public long getProfilerTime() {
125 return m_profilerTime;
126 }
127
128 /**
129 * Returns the time spend in the last run without the time
130 * spend by the profiler. It is the case that
131 * net_run_time = run_duration - profiler_time
132 */
133 public long getNetRunTime() {
134 return m_lastCheckTime - m_profilerTime;
135 };
136
137 /**
138 * Returns the time spend in the current run until the last check-point
139 * inclusive the time spend by the profiler. It is the case that
140 * net_run_time = run_duration - profiler_time
141 */
142 public long getRunDuration() {
143 return m_lastCheckTime;
144 // long auxTime1 = (System.currentTimeMillis() - m_startTime1000)/10;
145 // return ((double)auxTime1)/100;
146 } ;
147
148
149 /**
150 * Inialises the profiler for a new run
151 */
152 public String initRun(String runDescription) {
153 StringBuffer buf = new StringBuffer();
154 buf.append("-----------------------------------------------\n");
155 buf.append("New profiler run: " + runDescription);
156 buf.append("\n-----------------------------------------------\n");
157
158 m_maxMemory=0;
159 m_currMemory=0;
160 m_diffMemory=0;
161 m_profilerTime=0;
162 m_startTime = System.currentTimeMillis();
163 m_lastCheckTime=0;
164 m_lastDuration=0;
165
166 m_categorySums = new Hashtable();
167 m_categoryLasts = new Hashtable();
168 if ( m_doPrintToStdOut ) {
169 m_out.print(buf.toString());
170 }
171 return buf.toString();
172 } // initRun
173
174 /**
175 * To be called at all execution points of interest. Detects the time
176 * and memory usage in absolute terms as well as compared to the previous
177 * execution point
178 */
179 public String checkPoint(String execPointDescr) {
180 return checkPoint(execPointDescr, new String[0], true, true, true);
181 }
182
183 /**
184 * In addition to the variant of the method with two parameters allows:
185 * a set of categories (identified by strings) to which the preceeding
186 * fragment of code belongs; flag determining whether the description of
187 * the execution point to be displayed; flag determining whether the
188 * statistics to be shown
189 */
190 public String checkPoint(String execPointDescr, String categories[],
191 boolean showDescr, boolean showStats, boolean memoryCheck)
192 {
193 if (!m_enabled)
194 return "";
195
196 long currTime = System.currentTimeMillis() - m_startTime;
197 m_lastDuration = currTime - m_lastCheckTime;
198
199 if (memoryCheck) {
200 long oldMemory = m_currMemory;
201
202 if (m_garbageCollection) {
203 do {
204 m_currMemory = m_rt.totalMemory() - m_rt.freeMemory();
205 m_rt.gc();
206 try {wait(300);} catch (Exception e) {}
207 m_rt.gc();
208 } while (m_currMemory > m_rt.totalMemory() - m_rt.freeMemory());
209 }
210 else {
211 m_currMemory = m_rt.totalMemory() - m_rt.freeMemory();
212 }
213
214 m_currMemory /= 1000;
215 m_maxMemory = Math.max(m_maxMemory, m_currMemory);
216 m_diffMemory = m_currMemory - oldMemory;
217 } // if (memoryCheck)
218
219 m_lastCheckTime = System.currentTimeMillis() - m_startTime;
220 m_profilerTime += (m_lastCheckTime - currTime);
221
222 checkCategories(categories);
223 return showResults(execPointDescr, showDescr, showStats);
224 } // checkPoint
225
226 private void checkCategories(String categs[]) {
227 int size = categs.length;
228 String categ;
229 long last, sum;
230 Long l;
231 for (int i=0; i<size; i++) {
232 categ = categs[i].toUpperCase();
233 l = (Long)m_categorySums.get(categ);
234 sum = (l==null) ? 0 : l.longValue();
235 sum += m_lastDuration;
236 m_categorySums.put(categ, new Long(sum));
237 m_categoryLasts.put(categ, new Long(m_lastDuration));
238 } // for
239 } // checkCategories
240
241 private String showResults(String execPointDescr, boolean showDescr,
242 boolean showStats)
243 {
244 StringBuffer buff = new StringBuffer(500);
245 if (showDescr) {
246 buff.append("---------LOG: ");
247 buff.append(execPointDescr);
248 buff.append("---------");
249 }
250
251 if (showStats) {
252 buff.append("\nMemory: ");
253 buff.append(m_currMemory);
254 buff.append("k; change: ");
255 buff.append(m_diffMemory);
256 buff.append("k; max: ");
257 buff.append(m_maxMemory);
258 buff.append("k; Net time: ");
259 buff.append(printTime(getNetRunTime()));
260 buff.append("; since prev.: ");
261 buff.append(printTime(m_lastDuration));
262 // buff.append("; profiler time: ");
263 // buff.append(printTime(m_profilerTime));
264 // buff.append("; duration: ");
265 // buff.append(printTime(m_lastCheckTime));
266 }
267
268 if (buff.length() > 0 && m_doPrintToStdOut) {
269 m_out.println(buff.toString());
270 }
271 return buff.toString();
272 } // showResults
273
274 /**
275 * Returns 0 if the category was not found
276 */
277 public long getCategoryTimeSum(String category) {
278 Long sum = (Long)m_categorySums.get(category.toUpperCase());
279 return (sum == null) ? 0 : sum.longValue();
280 } // getCategoryTimeSum
281
282 /**
283 * Returns 0 if the category was not found
284 */
285 public long getCategoryTimeLast(String category) {
286 Long sum = (Long)m_categoryLasts.get(category.toUpperCase());
287 return (sum == null) ? 0 : sum.longValue();
288 } // getCategoryTimeSum
289
290 /**
291 * Prints the time for all the categories of activities
292 */
293 public void showCategoryTimes() {
294 m_out.println("Time spent by categories:");
295 Enumeration categNames = m_categorySums.keys();
296 String categ;
297 while (categNames.hasMoreElements()) {
298 categ = (String)categNames.nextElement();
299 showCategoryTime(categ);
300 } // while
301 } // showCategoryTimes
302
303 /**
304 * Prints the time for certain category of activities
305 */
306 public void showCategoryTime(String categ) {
307 m_out.println(categ + ", sum=" +
308 printTime(getCategoryTimeSum(categ)) +
309 ", last=" + printTime(getCategoryTimeLast(categ)));
310 } // showCategoryTimes
311
312 /**
313 * An auxiliary routine printing time in "nnn.nns" format
314 */
315 public String printTime(long timeMillis) {
316 long round = timeMillis/1000;
317 long remaind = (timeMillis % 1000)/10;
318 StringBuffer buff = new StringBuffer(10);
319 buff.append(round);
320 buff.append(".");
321 buff.append(remaind);
322 buff.append("s");
323 return buff.toString();
324 } // printTime
325
326 /**
327 * An auxiliary routine printing in a string speed
328 */
329 public String printSpeed(long timeMillis,
330 double whatever, String whateverMeasure)
331 {
332 double speed1000 = (double) whatever/ timeMillis;
333 long round = (long)((double)speed1000*1000);
334 long remaind = (long)(((double)speed1000*100000) - 100 * round);
335 StringBuffer buff = new StringBuffer(10);
336 buff.append(round);
337 buff.append(".");
338 buff.append(remaind);
339 buff.append(whateverMeasure);
340 buff.append("/s");
341 return buff.toString();
342 } // printTime
343
344 /**
345 * An auxiliary routine printing time, avg. time, and avg. speed for
346 * a category
347 */
348 public void printCategAvg(String categ, long items,
349 double volume, String whateverMeasure)
350 {
351 long time = getCategoryTimeSum(categ);
352 if (time==0) {
353 m_out.println("Category \"" + categ + "\" not found");
354 }
355
356 m_out.println("Category \"" + categ + "\", Time= " +
357 printTime(time) + "; avg. time= " +
358 printTime(time/items) + "; speed= " +
359 printSpeed(time, volume, whateverMeasure));
360 } // printCategAvg
361
362 /**
363 * Sets the profiler to print (or not) to the standard output.
364 * The default behaviour is - print to std out.
365 * @param doPrint whether or not to print to std out.
366 */
367 public void printToSystemOut(boolean doPrint){
368 m_doPrintToStdOut = doPrint;
369 } // printToSystemOut(doPrint);
370 } // Profiler