Profiler.java
001 /*
002  *  Profiler.java - A simple profiling utility
003  *
004  *  Copyright (c) 2001, OntoText Lab. (http://www.ontotext.com)
005  *
006  *  This file is part of GATE (see http://gate.ac.uk/), and is free
007  *  software, licenced under the GNU Library General Public License,
008  *  Version 2, June 1991 (in the distribution as file licence.html,
009  *  and also available at http://gate.ac.uk/gate/licence.html).
010  *
011  *  Atanas Kiryakov, 05/11/01
012  *
013  *  $Id: Profiler.java 17601 2014-03-08 18:56:22Z markagreenwood $
014  */
015 
016 
017 package gate.util.profile;
018 
019 /**
020  *  This is a simple "code-internal" profiler which can be used
021  *  by introducing calls to its methods (mostly, checkPoint()) in  the code.
022  *  It allows detection and reporting of time and memory usage
023  *  between execution points as well as for the whole run. In addition allows
024  *  for collection/reporting of the resources usage by categories (types of
025  *  activity performed between the check point and the previous one).
026  *  The results are currently just dumped to the output.
027  *  <p>
028  *  Important feature is the possibility of the memory usage measurment code
029  *  to call the Garbage Collector following a specific strategy that allows
030  *  the real memory usage to be deteceted. This feature can be switched OFF
031  *  if appropriate, for example, if the *real* run-time memory usage have to
032  *  be measured rather than the precise but ideallistic one provided otherwise.
033  *  <p>
034  *  The profiler can be switched OFF using the enable(boolean) method. In such
035  *  case it ignores any calls to its checkPoint(...) method, so, basically does
036  *  nothing. This feature is usefull in cases when the profiler have to be
037  *  "stripped" from the code in order to allow non-disturbed execution.
038  *  <p>
039  *  The profiler takes care to calculate the time exlusive its footprint. It
040  *  takes account for both "net" time and the absolute duration. Also in
041  *  relation to the execution time measurment - it depends on the speed of the
042  *  machine as well as on the other applications running in parallel.
043  */
044 
045 //import java.io.PrintStream;
046 import java.util.HashMap;
047 import java.util.Iterator;
048 import java.util.Map;
049 
050 import org.apache.log4j.Logger;
051 
052 public class Profiler {
053   protected static final Logger log = Logger.getLogger(Profiler.class);
054 
055   //private PrintStream m_out;
056   private boolean m_enabled = true;
057   private boolean m_garbageCollection = true;
058   /** Indicates whether just to return the string dumps (false) or also print them
059    to the std out (true)*/
060   private boolean m_doPrintToStdOut = true;
061 
062   // keeps the sum of the time spend on a category of tasks
063   // the categories are identified via strings which are used as
064   // keys in the table. The values in the table are Long objects, millisec.
065   private Map<String,Long> m_categorySums;
066 
067   // keeps the time spend on the last task of a category
068   // the categories are identified via strings which are used as
069   // keys in the table. The values in the table are Long objects, millisec.
070   private Map<String,Long> m_categoryLasts;
071 
072   private Runtime m_rt;
073 
074   // all the time constants below in 1/1000s
075   // the time when the profiler was intiated for the current run
076   private long m_startTime;
077   private long m_lastCheckTime, m_profilerTime, m_lastDuration;
078 
079   private long m_maxMemory, m_currMemory, m_diffMemory;
080 
081   public Profiler() {
082     m_rt = Runtime.getRuntime();
083     //m_out = System.out;
084   }
085 
086   /**
087    * Switches the profiler ON and OFF. When OFF all the methods do nothing
088    */
089   public void enable(boolean isEnabled) {
090     m_enabled = isEnabled;
091   // enable
092 
093   /**
094    * Answers is the profiler switched ON or OFF. When OFF all the methods do
095    * nothing
096    */
097   public boolean isEnabled() {
098     return m_enabled;
099   }
100 
101   /**
102    * Tell's the profiler whether to call the garbage collector when detecting
103    * memory usage or not. If switched ON the GC is called following a
104    * specific strategy as many time as needed so to collect all the memory
105    * that can be collected. This makes the profiling slower and also does not
106    * correctly account for the really memory usage of the applicaton when
107    * run without the profiler. On the other hand, with garbage collection, it
108    * is easier to detecet the amount of memory really necessary for the
109    * application.
110    */
111   public void enableGCCalling(boolean collect) {
112     m_garbageCollection = collect;
113   }
114 
115   /**
116    @see #enableGCCalling(boolean)
117    */
118   public boolean isGCCallingEnabled() {
119     return m_garbageCollection;
120   }
121 
122 
123   /**
124    * Returns the time spend by the profiler during the last run. It is the
125    * case that
126    *      net_run_time = run_duration - profiler_time
127    */
128   public long getProfilerTime() {
129     return m_profilerTime;
130   }
131 
132   /**
133    * Returns the time spend in the last run without the time
134    * spend by the profiler. It is the case that
135    *      net_run_time = run_duration - profiler_time
136    */
137   public long getNetRunTime() {
138     return m_lastCheckTime - m_profilerTime;
139   };
140 
141   /**
142    * Returns the time spend in the current run until the last check-point
143    * inclusive the time spend by the profiler. It is the case that
144    *      net_run_time = run_duration - profiler_time
145    */
146   public long getRunDuration() {
147     return m_lastCheckTime;
148 //        long auxTime1 = (System.currentTimeMillis() - m_startTime1000)/10;
149 //        return ((double)auxTime1)/100;
150   ;
151 
152   public long getLastDuration() {
153     return m_lastDuration;
154   }
155 
156 
157   /**
158    * Inialises the profiler for a new run
159    */
160   public String initRun(String runDescription) {
161     StringBuffer buf = new StringBuffer();
162     buf.append("-----------------------------------------------\n");
163     buf.append("New profiler run: " + runDescription);
164     buf.append("\n-----------------------------------------------\n");
165 
166     m_maxMemory=0;
167     m_currMemory=0;
168     m_diffMemory=0;
169     m_profilerTime=0;
170     m_startTime = System.currentTimeMillis();
171     m_lastCheckTime=0;
172     m_lastDuration=0;
173 
174     m_categorySums = new HashMap<String,Long>();
175     m_categoryLasts = new HashMap<String,Long>();
176     if m_doPrintToStdOut ) {
177       log.debug(buf.toString());
178     }
179     return buf.toString();
180   // initRun
181 
182   /**
183    * To be called at all execution points of interest. Detects the time
184    * and memory usage in absolute terms as well as compared to the previous
185    * execution point
186    */
187   public String checkPoint(String execPointDescr) {
188     return checkPoint(execPointDescr, new String[0], true, true, true);
189   }
190 
191   /**
192    * In addition to the variant of the method with two parameters allows:
193    * a set of categories (identified by strings) to which the preceeding
194    * fragment of code belongs; flag determining whether the description of
195    * the execution point to be displayed; flag determining whether the
196    * statistics to be shown
197    */
198   public String checkPoint(String execPointDescr, String categories[],
199       boolean showDescr, boolean showStats, boolean memoryCheck)
200   {
201     if (!m_enabled)
202       return "";
203 
204     long currTime = System.currentTimeMillis() - m_startTime;
205     m_lastDuration = currTime - m_lastCheckTime;
206 
207     if (memoryCheck) {
208       long oldMemory = m_currMemory;
209 
210       if (m_garbageCollection) {
211         do {
212           m_currMemory = m_rt.totalMemory() - m_rt.freeMemory();
213           m_rt.gc();
214           try {
215             wait(300);
216           catch(Exception e) {
217             //ignore this as it should never really happen
218           }
219           m_rt.gc();
220         while (m_currMemory > m_rt.totalMemory() - m_rt.freeMemory());
221       }
222       else {
223         m_currMemory = m_rt.totalMemory() - m_rt.freeMemory();
224       }
225 
226       m_currMemory /= 1000;
227       m_maxMemory = Math.max(m_maxMemory, m_currMemory);
228       m_diffMemory = m_currMemory - oldMemory;
229     // if (memoryCheck)
230 
231     m_lastCheckTime = System.currentTimeMillis() - m_startTime;
232     m_profilerTime += (m_lastCheckTime - currTime);
233 
234     checkCategories(categories);
235     return showResults(execPointDescr, showDescr, showStats);
236   // checkPoint
237 
238   private void checkCategories(String categs[]) {
239     int size = categs.length;
240     String categ;
241     long sum;
242     Long l;
243     for (int i=0; i<size; i++) {
244       categ = categs[i].toUpperCase();
245       l = m_categorySums.get(categ);
246       sum = (l==null: l.longValue();
247       sum += m_lastDuration;
248       m_categorySums.put(categ, new Long(sum));
249       m_categoryLasts.put(categ, new Long(m_lastDuration));
250     // for
251   // checkCategories
252 
253   private String showResults(String execPointDescr, boolean showDescr,
254       boolean showStats)
255   {
256     StringBuffer buff = new StringBuffer(500);
257     if (showDescr) {
258       buff.append("---------LOG: ");
259       buff.append(execPointDescr);
260       buff.append("---------");
261     }
262 
263     if (showStats) {
264       buff.append("\nMemory: ");
265       buff.append(m_currMemory);
266       buff.append("k; change: ");
267       buff.append(m_diffMemory);
268       buff.append("k; max: ");
269       buff.append(m_maxMemory);
270       buff.append("k; Net time:   ");
271       buff.append(printTime(getNetRunTime()));
272       buff.append("; since prev. millisecs: ");
273       buff.append(m_lastDuration);
274 //            buff.append("; profiler time: ");
275 //            buff.append(printTime(m_profilerTime));
276 //            buff.append("; duration: ");
277 //            buff.append(printTime(m_lastCheckTime));
278     }
279 
280     if (buff.length() && m_doPrintToStdOut) {
281         log.debug(buff.toString());
282     }
283     return buff.toString();
284   // showResults
285 
286   /**
287    * Returns 0 if the category was not found
288    */
289   public long getCategoryTimeSum(String category) {
290     Long sum = m_categorySums.get(category.toUpperCase());
291     return (sum == null: sum.longValue();
292   // getCategoryTimeSum
293 
294   /**
295    * Returns 0 if the category was not found
296    */
297   public long getCategoryTimeLast(String category) {
298     Long sum = m_categoryLasts.get(category.toUpperCase());
299     return (sum == null: sum.longValue();
300   // getCategoryTimeSum
301 
302   /**
303    * Prints the time for all the categories of activities
304    */
305   public void showCategoryTimes() {
306     log.debug("Time spent by categories:");
307     Iterator<String> categNames = m_categorySums.keySet().iterator();
308     String categ;
309     while (categNames.hasNext()) {
310       categ = categNames.next();
311       showCategoryTime(categ);
312     // while
313   // showCategoryTimes
314 
315   /**
316    * Prints the time for certain category of activities
317    */
318   public void showCategoryTime(String categ) {
319     log.debug(categ + ", sum=" +
320             printTime(getCategoryTimeSum(categ)) +
321             ", last=" + printTime(getCategoryTimeLast(categ)));
322   // showCategoryTimes
323 
324   /**
325    * An auxiliary routine printing time in "nnn.nns" format
326    */
327   public String printTime(long timeMillis) {
328     long round = timeMillis/1000;
329     long remaind = (timeMillis % 1000)/10;
330     StringBuffer buff = new StringBuffer(10);
331     buff.append(round);
332     buff.append(".");
333     buff.append(remaind);
334     buff.append("s");
335     return buff.toString();
336   // printTime
337 
338   /**
339    * An auxiliary routine printing in a string speed
340    */
341   public String printSpeed(long timeMillis,
342       double whatever, String whateverMeasure)
343   {
344     double speed1000 = whatever/ timeMillis;
345     long round = (long)(speed1000*1000);
346     long remaind =  (long)((speed1000*100000100 * round);
347     StringBuffer buff = new StringBuffer(10);
348     buff.append(round);
349     buff.append(".");
350     buff.append(remaind);
351     buff.append(whateverMeasure);
352     buff.append("/s");
353     return buff.toString();
354   // printTime
355 
356   /**
357    * An auxiliary routine printing time, avg. time, and avg. speed for
358    * a category
359    */
360   public void printCategAvg(String categ, long items,
361       double volume, String whateverMeasure)
362   {
363     long time = getCategoryTimeSum(categ);
364     if (time==0) {
365       log.debug("Category \"" + categ + "\" not found");
366     }
367 
368     log.debug("Category \"" + categ + "\",  Time= " +
369         printTime(time"; avg. time= " +
370         printTime(time/items+  "; speed= " +
371         printSpeed(time, volume, whateverMeasure));
372   // printCategAvg
373 
374   /**
375    * Sets the profiler to print (or not) to the standard output.
376    * The default behaviour is - print to std out.
377    @param doPrint whether or not to print to std out.
378    */
379   public void printToSystemOut(boolean doPrint){
380     m_doPrintToStdOut = doPrint;
381   // printToSystemOut(doPrint);
382 // Profiler