Benchmark.java
001 /*
002  *  Benchmark.java
003  *
004  *  Copyright (c) 1995-2012, The University of Sheffield. See the file
005  *  COPYRIGHT.txt in the software or at http://gate.ac.uk/gate/COPYRIGHT.txt
006  *
007  *  This file is part of GATE (see http://gate.ac.uk/), and is free
008  *  software, licenced under the GNU Library General Public License,
009  *  Version 2, June 1991 (in the distribution as file licence.html,
010  *  and also available at http://gate.ac.uk/gate/licence.html).
011  */
012 
013 package gate.util;
014 
015 import gate.Executable;
016 import gate.creole.ExecutionException;
017 
018 import java.util.HashMap;
019 import java.util.Map;
020 
021 import org.apache.log4j.Logger;
022 
023 /**
024  * This class provides methods for making entries in the shared log
025  * maintained by the GATE system. User should use various methods
026  * provided by this class and as described in the following example.
027  
028  <p>
029  
030  * TODO: Provide example here.
031  
032  </p>
033  
034  @author niraj
035  */
036 public class Benchmark {
037 
038   /**
039    * variable that keeps track of if logging is ON or OFF.
040    */
041   protected static boolean benchmarkingEnabled = false;
042 
043   /**
044    * corpus name feature
045    */
046   public final static String CORPUS_NAME_FEATURE = "corpusName";
047 
048   /**
049    * application name feature
050    */
051   public final static String APPLICATION_NAME_FEATURE = "applicationName";
052 
053   /**
054    * document name feature
055    */
056   public final static String DOCUMENT_NAME_FEATURE = "documentName";
057 
058   /**
059    * processing resource name feature
060    */
061   public final static String PR_NAME_FEATURE = "prName";
062 
063   /**
064    * message feature
065    */
066   public final static String MESSAGE_FEATURE = "message";
067 
068   // various check point ids
069 
070   public final static String PR_PREFIX = "pr_";
071 
072   public final static String DOCUMENT_LOADED = "documentLoaded";
073 
074   public final static String DOCUMENT_SAVED = "documentSaved";
075 
076   public final static String WRITING_FVS_TO_DISK = "writingFVsToDisk";
077 
078   public final static String ANNOTS_TO_NLP_FEATURES = "annotsToNlpFeatures";
079 
080   public final static String NLP_FEATURES_TO_FVS = "nlpFeaturesToFVs";
081 
082   public final static String READING_LEARNING_INFO = "readingLearningInfo";
083 
084   public final static String MODEL_APPLICATION = "modelApplication";
085 
086   public final static String WRITING_NGRAM_MODEL = "writingNgramModel";
087 
088   public final static String TERM_DOC_STATS = "termDocStats";
089 
090   public final static String FILTERING = "filtering";
091 
092   public final static String MODEL_TRAINING = "modelTraining";
093 
094   public final static String EVALUATION = "evaluation";
095 
096   public final static String NLP_LABELS_TO_DATA_LABELS = "nlpLabelsToDataLabels";
097 
098   public final static String READING_NLP_FEATURES = "readingNlpFeatures";
099 
100   public final static String READING_FVS = "readingFVs";
101 
102   public final static String WEKA_MODEL_TRAINING = "wekaModelTraining";
103 
104   public final static String PAUM_MODEL_TRAINING = "paumModelTraining";
105 
106   public final static String READING_CHUNK_LEARNING_DATA = "readingChunkLearningData";
107 
108   public final static String WEKA_MODEL_APPLICATION = "wekaModelApplication";
109 
110   public final static String PAUM_MODEL_APPLICATION = "paumModelApplication";
111 
112   public final static String POST_PROCESSING = "postProcessing";
113 
114   /**
115    * Static shared logger used for logging.
116    */
117   public static final Logger logger = Logger.getLogger(Benchmark.class);
118 
119   /**
120    * This returns the current system time.
121    */
122   public static long startPoint() {
123     return System.currentTimeMillis();
124   }
125 
126   /**
127    * Like {@link #startPoint()} but also logs a message with the
128    * starting time if benchmarking is enabled. This is intended to be
129    * used in conjuntion with the three-argument version of checkPoint.
130    
131    @param benchmarkID the identifier of the process that is just
132    *          starting.
133    @return the current time, as logged.
134    */
135   public static long startPoint(String benchmarkID) {
136     long time = startPoint();
137     if(benchmarkingEnabled) {
138       logger.info(time + " START " + benchmarkID);
139     }
140     return time;
141   }
142 
143   /**
144    * This method is responsible for making entries into the log.
145    
146    @param startTime - when did the actual process started. This value
147    *          should be the value obtained by Benchmark.startPoint()
148    *          method invoked at the begining of the process.
149    @param benchmarkID - a unique ID of the resource that should be
150    *          logged with this message.
151    @param objectInvokingThisCheckPoint - The benchmarkable object that
152    *          invokes this method.
153    @param benchmarkingFeatures - any features (key-value pairs) that should be
154    *          reported in the log message. toString() method will be
155    *          invoked on the objects.
156    */
157   public static void checkPoint(long startTime, String benchmarkID,
158           Object objectInvokingThisCheckPoint, Map<Object,Object> benchmarkingFeatures) {
159 
160     // check if logging is disabled
161     if(!benchmarkingEnabledreturn;
162 
163     // we calculate processEndTime here as we don't want to consider
164     // the time to convert featureMapToString
165     long processingTime = System.currentTimeMillis() - startTime;
166 
167     logCheckPoint(String.valueOf(processingTime), benchmarkID,
168             objectInvokingThisCheckPoint, benchmarkingFeatures);
169   }
170   
171   /**
172    * This method is responsible for making entries into the log.
173    
174    @param totalTime - Total time consumed by the process
175    @param benchmarkID - a unique ID of the resource that should be
176    *          logged with this message.
177    @param objectInvokingThisCheckPoint - The benchmarkable object that
178    *          invokes this method.
179    @param benchmarkingFeatures - any features (key-value pairs) that should be
180    *          reported in the log message. toString() method will be
181    *          invoked on the objects.
182    */
183   public static void checkPointWithDuration(long totalTime, String benchmarkID,
184           Object objectInvokingThisCheckPoint, Map<Object,Object> benchmarkingFeatures) {
185 
186     // check if logging is disabled
187     if(!benchmarkingEnabledreturn;
188 
189     logCheckPoint(String.valueOf(totalTime), benchmarkID,
190             objectInvokingThisCheckPoint, benchmarkingFeatures);
191   }
192 
193   /**
194    * Logs the end of a process. There must previously have been a call
195    * to {@link #startPoint(String)} with the same benchmark ID.
196    
197    @see #checkPoint(long, String, Object, Map)
198    */
199   public static void checkPoint(String benchmarkID,
200           Object objectInvokingThisCheckPoint, Map<Object,Object> benchmarkingFeatures) {
201     if(!benchmarkingEnabledreturn;
202     logCheckPoint("END", benchmarkID, objectInvokingThisCheckPoint,
203             benchmarkingFeatures);
204   }
205 
206   /**
207    * Private method to create a line in the benchmark log.
208    
209    @param processingTimeOrFlag either the duration of the task in ms
210    *          or the string "END" if no start time was provided.
211    */
212   private static void logCheckPoint(String processingTimeOrFlag,
213           String benchmarkID, Object objectInvokingThisCheckPoint,
214           Map<Object,Object> benchmarkingFeatures) {
215     // finally build the string to be logged
216     StringBuilder messageToLog = new StringBuilder();
217     messageToLog.append("" + System.currentTimeMillis() " ");
218     messageToLog.append(processingTimeOrFlag + " " + benchmarkID + " "
219             + objectInvokingThisCheckPoint.getClass().getName() " ");
220 
221     if(benchmarkingFeatures == null) {
222       messageToLog.append("{}");
223     }
224     else {
225       messageToLog.append(benchmarkingFeatures.toString().replaceAll("\n"""))
226             .append("\n");
227     }
228     logger.info(messageToLog.toString());
229   }
230 
231   /**
232    * Helper method to generate the benchmark ID.
233    */
234   public static String createBenchmarkId(String resourceName,
235           String parentBenchmarkID) {
236     if(parentBenchmarkID != null) {
237       if(resourceName != null) {
238         return (parentBenchmarkID + "." + resourceName.replaceAll("\\.","_")).replaceAll("[ ]+""_");
239       }
240       else {
241         return (parentBenchmarkID + ".null").replaceAll("[ ]+""_");
242       }
243     }
244     else {
245       if(resourceName != null) {
246         return resourceName.replaceAll("[ .]+""_");
247       }
248       else {
249         return "null";
250       }
251     }
252 
253   }
254 
255   /**
256    * Returns if the logging is enabled.
257    */
258   public static boolean isBenchmarkingEnabled() {
259     return benchmarkingEnabled;
260   }
261 
262   /**
263    * Enables or disables the logging.
264    
265    @param benchmarkingEnabled
266    */
267   public static void setBenchmarkingEnabled(boolean benchmarkingEnabled) {
268     Benchmark.benchmarkingEnabled = benchmarkingEnabled;
269   }
270 
271   /**
272    * Executes the given {@link Executable}, logging its runtime under
273    * the given benchmark ID (which is propagated to the Executable if it
274    * is itself {@link Benchmarkable}).
275    
276    @param executable the object to execute
277    @param benchmarkID the benchmark ID, which must not contain spaces
278    *  as it is already used as a separator in the log, you can use
279    {@link #createBenchmarkId(String, String)} for it. 
280    @param objectInvokingThisCheckPoint the object invoking this method
281    *          (typically the caller would pass <code>this</code> here)
282    @param benchmarkingFeatures features to include in the check point
283    *          log
284    @throws ExecutionException any exceptions thrown by the underlying
285    *           Executable are propagated.
286    */
287   public static void executeWithBenchmarking(Executable executable,
288           String benchmarkID, Object objectInvokingThisCheckPoint,
289           Map<Object,Object> benchmarkingFeaturesthrows ExecutionException {
290     if(!benchmarkingEnabled) {
291       executable.execute();
292     }
293     else {
294       long startTime = startPoint();
295       String savedBenchmarkID = null;
296       try {
297         if(executable instanceof Benchmarkable) {
298           savedBenchmarkID = ((Benchmarkable)executable).getBenchmarkId();
299           ((Benchmarkable)executable).setBenchmarkId(benchmarkID);
300         }
301 
302         executable.execute();
303       }
304       catch(Exception e) {
305         Map<Object,Object> tempFeatures = new HashMap<Object,Object>();
306         if(benchmarkingFeatures != null) {
307           tempFeatures.putAll(benchmarkingFeatures);
308         }
309         tempFeatures.put("exceptionThrown", e);
310         checkPoint(startTime, benchmarkID, objectInvokingThisCheckPoint,
311                 tempFeatures);
312         if(instanceof ExecutionException) {
313           throw (ExecutionException)e;
314         }
315         else {
316           throw (RuntimeException)e;
317         }
318       }
319       finally {
320         if(savedBenchmarkID != null) {
321           ((Benchmarkable)executable).setBenchmarkId(savedBenchmarkID);
322         }
323       }
324 
325       // succeeded, so log checkpoint with the original features
326       checkPoint(startTime, benchmarkID, objectInvokingThisCheckPoint,
327               benchmarkingFeatures);
328     }
329   }
330 }