001 /*
002 * This file is part of the Jikes RVM project (http://jikesrvm.org).
003 *
004 * This file is licensed to You under the Eclipse Public License (EPL);
005 * You may not use this file except in compliance with the License. You
006 * may obtain a copy of the License at
007 *
008 * http://www.opensource.org/licenses/eclipse-1.0.php
009 *
010 * See the COPYRIGHT.txt file distributed with this work for information
011 * regarding copyright ownership.
012 */
013 package org.jikesrvm.adaptive.util;
014
015 import java.io.FileOutputStream;
016 import java.io.IOException;
017 import java.io.PrintStream;
018
019 import org.jikesrvm.VM;
020 import org.jikesrvm.adaptive.controller.Controller;
021 import org.jikesrvm.adaptive.controller.ControllerMemory;
022 import org.jikesrvm.adaptive.controller.ControllerPlan;
023 import org.jikesrvm.adaptive.controller.HotMethodEvent;
024 import org.jikesrvm.adaptive.recompilation.CompilerDNA;
025 import org.jikesrvm.classloader.NormalMethod;
026 import org.jikesrvm.classloader.RVMMethod;
027 import org.jikesrvm.compilers.common.CompiledMethod;
028 import org.jikesrvm.compilers.common.RuntimeCompiler;
029 import org.jikesrvm.compilers.opt.driver.CompilationPlan;
030 import org.jikesrvm.runtime.Time;
031
032 /**
033 * This class provides logging functionality for the Adaptive Optimization System.
034 * <p>
035 * Right now this is fairly primitive, an evolving number of events are
036 * defined and log entries are quite unsophisticated.
037 * <p>
038 * Some obvious TODO items:
039 * <ul>
040 * <li>compact encoding of log entries
041 * <li>some notion of log format versions
042 * <li>When is the log file flushed and closed?
043 * <li>Do we want to put report() information in the log?
044 * <li> ...
045 * </ul>
046 * <p>
047 * NOTE: All code that writes to the log is synchronized on the PrintStream
048 * object to avoid interspersed messages, which can happen when the
049 * compilation thread and the controller thread try to log a message
050 * "at the same time".
051 * <p>
052 * The current logging levels are:
053 * <ul>
054 * <li>0 Do no logging
055 * <li>1 Do minimal logging at startup and VM exit.
056 * If at all possible, do not log anything during program execution.
057 * This logging level is supposed to produce minimal performance pertubation.
058 * <li>2 Log interesting AOS events and controller actions
059 * <li>3 Exhaustively log pretty much everything that is going on
060 * </ul>
061 */
062 public final class AOSLogging {
063
064 /** Singleton instance of the logger */
065 public static final AOSLogging logger = new AOSLogging();
066
067 /*
068 * The output file stream, where all log messages will go
069 */
070 private PrintStream log;
071
072 /**
073 * Returns the log object
074 */
075 public PrintStream getLog() {
076 return log;
077 }
078
079 /*
080 * Record that the AOS logging has been booted.
081 * Needed to allow fast exit from reporting to ensure
082 * that when no class is specified to be run but "-help" is specified,
083 * don't want null pointer exception to occur!
084 */
085 private boolean booted = false;
086
087 /**
088 * Return whether AOS logging has booted.
089 * @return whether AOS logging has booted
090 */
091 public boolean booted() {
092 return booted;
093 }
094
095 /**
096 * Helper routine to produce the current time as a string
097 */
098 private String getTime() {
099 return Controller.controllerClock + ":" + Time.nanoTime();
100 }
101
102 /**
103 * Called from ControllerThread.run to initialize the logging subsystem
104 */
105 public void boot() {
106 if (Controller.options.LOGGING_LEVEL >= 1) {
107 try {
108 log = new PrintStream(new FileOutputStream(Controller.options.LOGFILE_NAME));
109
110 // This statement will force the compilation of println, so it
111 // is needed regardless of the particular content of the message!
112 synchronized (log) {
113 log.println(getTime() + " Logging enabled\n");
114 log.println(Controller.options);
115 }
116 } catch (IOException e) {
117 VM.sysWrite("IOException caught in AOSLogging.java while trying to create and start log file.\n");
118 VM.sysWrite("Please check for file permission problems\n");
119 }
120 }
121 booted = true;
122 }
123
124 ////////////////////////////////////////////////////////////////
125 // Logging level 1
126 ////////////////////////////////////////////////////////////////
127
128 /**
129 * Call this method to dump statistics related to decaying
130 * @param decayCount the number of decay events
131 */
132 public void decayStatistics(int decayCount) {
133 if (!booted) return; // fast exit
134 if (Controller.options.LOGGING_LEVEL >= 1) {
135 synchronized (log) {
136 log.print(getTime() + " Decay Organizer Statistics: \n\t" + " Num of Decay events: " + decayCount + "\n");
137 }
138 }
139 }
140
141 /**
142 * Call this method when one run of the application begins
143 */
144 public void recompilingAllDynamicallyLoadedMethods() {
145 if (Controller.options.LOGGING_LEVEL >= 1) {
146 synchronized (log) {
147 log.println(getTime() + " Recompiling all dynamically loaded methods");
148 }
149 }
150 }
151
152 /**
153 * Dumps lots of controller statistics to the log file
154 */
155 public void printControllerStats() {
156 if (Controller.options.LOGGING_LEVEL >= 1) {
157 int awoken = ControllerMemory.getNumAwoken();
158 int didNothing = ControllerMemory.getNumDidNothing();
159 int numMethodsConsidered = ControllerMemory.getNumMethodsConsidered();
160 int numMethodsScheduledForRecomp = ControllerMemory.getNumMethodsScheduledForRecomp();
161 int numOpt0 = ControllerMemory.getNumOpt0();
162 int numOpt1 = ControllerMemory.getNumOpt1();
163 int numOpt2 = ControllerMemory.getNumOpt2();
164 int numOpt3 = ControllerMemory.getNumOpt3();
165
166 synchronized (log) {
167 log.print(getTime() +
168 "\n Num times Controller thread is awoken: " +
169 awoken +
170 "\n Num times did nothing: " +
171 didNothing +
172 " (" +
173 ((int) ((float) didNothing / (float) awoken * 100)) +
174 "%)\n Num methods baseline compiled: " +
175 ControllerMemory.getNumBase() +
176 "\n Num methods considered for recompilation: " +
177 numMethodsConsidered +
178 "\n Num methods chosen to recompile: " +
179 numMethodsScheduledForRecomp +
180 " (" +
181 ((int) ((float) numMethodsScheduledForRecomp / numMethodsConsidered * 100)) +
182 "%)\n Opt Levels Chosen: " +
183 "\n\t Opt Level 0: " +
184 numOpt0 +
185 " (" +
186 ((int) ((float) numOpt0 / numMethodsScheduledForRecomp * 100)) +
187 "%)\n\t Opt Level 1: " +
188 numOpt1 +
189 " (" +
190 ((int) ((float) numOpt1 / numMethodsScheduledForRecomp * 100)) +
191 "%)\n" +
192 "\t Opt Level 2: " +
193 numOpt2 +
194 " (" +
195 ((int) ((float) numOpt2 / numMethodsScheduledForRecomp * 100)) +
196 "%)\n" +
197 "\t Opt Level 3: " +
198 numOpt3 +
199 " (" +
200 ((int) ((float) numOpt3 / numMethodsScheduledForRecomp * 100)) +
201 "%)\n\n");
202
203 // Let the controller memory summarize itself to the log file
204 ControllerMemory.printFinalMethodStats(log);
205 }
206 }
207 }
208
209 /**
210 * This method reports the basic speedup rate for a compiler
211 * @param compiler the compiler you are reporting about
212 * @param rate the speedup rate
213 */
214 public void reportSpeedupRate(int compiler, double rate) {
215 if (Controller.options.LOGGING_LEVEL >= 1) {
216 synchronized (log) {
217 log.println(getTime() +
218 " SpeedupRate for " +
219 CompilerDNA.getCompilerString(compiler) +
220 " compiler: " +
221 rate);
222 }
223 }
224 }
225
226 /**
227 * This method reports the basic compilation rate for a compiler
228 * @param compiler the compiler you are reporting about
229 * @param rate the compilation rate (bytecodes per millisecond)
230 */
231 public void reportCompilationRate(int compiler, double rate) {
232 if (Controller.options.LOGGING_LEVEL >= 1) {
233 synchronized (log) {
234 log.println(getTime() +
235 " Compilation Rate (bytecode/msec) for " +
236 CompilerDNA.getCompilerString(compiler) +
237 " compiler: " +
238 rate);
239 }
240 }
241 }
242
243 /**
244 * This method reports the benefit ratio from one compiler to the other
245 * @param compiler1 the first compiler
246 * @param compiler2 the second compiler
247 * @param rate the improvement from going from a compiler1-compiled method
248 * to a compiler2-compiled method
249 */
250 public void reportBenefitRatio(int compiler1, int compiler2, double rate) {
251 if (Controller.options.LOGGING_LEVEL >= 1) {
252 synchronized (log) {
253 log.println(getTime() +
254 " Benefit Ratio from " +
255 CompilerDNA.getCompilerString(compiler1) +
256 " compiler to " +
257 CompilerDNA.getCompilerString(compiler2) +
258 " compiler: " +
259 rate);
260 }
261 }
262 }
263
264 /**
265 * This method reports the compile time ratio from one compiler to
266 * the other
267 * @param compiler1 the first compiler
268 * @param compiler2 the second compiler
269 * @param rate the ratio of compiler1 compilation rate to
270 * compiler2 compilation rate
271 */
272 public void reportCompileTimeRatio(int compiler1, int compiler2, double rate) {
273 if (Controller.options.LOGGING_LEVEL >= 1) {
274 synchronized (log) {
275 log.println(getTime() +
276 " Compile Time Ratio of " +
277 CompilerDNA.getCompilerString(compiler1) +
278 " compiler to " +
279 CompilerDNA.getCompilerString(compiler2) +
280 " compiler: " +
281 rate);
282 }
283 }
284 }
285
286 ////////////////////////////////////////////////////////////////
287 // Logging level 2
288 ////////////////////////////////////////////////////////////////
289
290 /**
291 * This method logs the scheduling of a recompilation,
292 * i.e., it being inserted in the compilation queue.
293 * @param plan the Compilation plan being executed.
294 * @param priority a number from 0.0 to 1.0 encoding the plan's priority.
295 */
296 public void recompilationScheduled(CompilationPlan plan, double priority) {
297 if (Controller.options.LOGGING_LEVEL >= 2) {
298 synchronized (log) {
299 log.println(getTime() + " Scheduling level " + plan.options.getOptLevel() + " recompilation of " + plan
300 .method + " (plan has priority " + priority + ")");
301 }
302 }
303 }
304
305 /**
306 * This method logs the beginning of an adaptively selected recompilation
307 * @param plan the Compilation plan being executed.
308 */
309 public void recompilationStarted(CompilationPlan plan) {
310 if (Controller.options.LOGGING_LEVEL >= 2) {
311 synchronized (log) {
312 log.println(getTime() + " Recompiling (at level " + plan.options.getOptLevel() + ") " + plan.method);
313 }
314 }
315 }
316
317 /**
318 * This method logs the successful completion of an adaptively
319 * selected recompilation
320 * @param plan the Compilation plan being executed.
321 */
322 public void recompilationCompleted(CompilationPlan plan) {
323 if (Controller.options.LOGGING_LEVEL >= 2) {
324 synchronized (log) {
325 // log.println(getTime() +" Recompiled (at level "+
326 // plan.options.getOptLevel() +") " +plan.method);
327 log.println(getTime() + " Recompiled (at level " + plan.options.getOptLevel() + ") " + plan.method);
328 }
329 }
330 }
331
332 /**
333 * This method logs the abortion of an adaptively selected recompilation
334 * @param plan the Compilation plan being executed.
335 */
336 public void recompilationAborted(CompilationPlan plan) {
337 if (Controller.options.LOGGING_LEVEL >= 2) {
338 synchronized (log) {
339 log.println(getTime() + " Failed recompiling (at level " + plan.options.getOptLevel() + " " + plan.method);
340 }
341 }
342 }
343
344 /**
345 * This method logs the actual compilation time for the given compiled method.
346 * @param cm the compiled method
347 * @param expectedCompilationTime the model-derived expected compilation time
348 */
349 public void recordCompileTime(CompiledMethod cm, double expectedCompilationTime) {
350 if (log != null && Controller.options.LOGGING_LEVEL >= 2) {
351 synchronized (log) {
352 double compTime = cm.getCompilationTime();
353 log.println(getTime() +
354 " Compiled " +
355 cm.getMethod() +
356 " with " +
357 cm.getCompilerName() +
358 " in " +
359 compTime +
360 " ms" +
361 ", model estimated: " +
362 expectedCompilationTime +
363 " ms" +
364 ", rate: " +
365 (((NormalMethod) cm.getMethod()).getBytecodeLength() / compTime));
366 }
367 }
368 }
369
370 /**
371 * this method logs the event when the controller discovers a method that has
372 * been recompiled and the previous version is still regarded as hot,
373 * i.e., still on the stack and significant.
374 */
375 public void oldVersionStillHot(HotMethodEvent hme) {
376 if (Controller.options.LOGGING_LEVEL >= 2) {
377 synchronized (log) {
378 log.println(getTime() + " Found a method with an old version still hot " + hme);
379 }
380 }
381 }
382
383 /**
384 * This method logs when the decay organizer runs.
385 */
386 public void decayingCounters() {
387 if (Controller.options.LOGGING_LEVEL >= 2) {
388 synchronized (log) {
389 log.println(getTime() + " Decaying clock and decayable objects");
390 }
391 }
392 }
393
394 /**
395 * This Method logs when the organizer thread has reached its
396 * sampling threshold
397 */
398 public void organizerThresholdReached() {
399 if (Controller.options.LOGGING_LEVEL >= 2) {
400 synchronized (log) {
401 log.println(getTime() + " OrganizerThread reached sample size threshold\n");
402 }
403 }
404 }
405
406 /**
407 * This method logs that the controller is notified of a
408 * candidate to be recompiled due to hotness;
409 * i.e., the method has been inserted in the controller queue.
410 * @param hotMethod method to be recompiled, and
411 * @param numSamples number of samples attributed to the method
412 */
413 public void controllerNotifiedForHotness(CompiledMethod hotMethod, double numSamples) {
414 if (Controller.options.LOGGING_LEVEL >= 2) {
415 synchronized (log) {
416 log.println(getTime() +
417 " Controller notified that method " +
418 hotMethod.getMethod() +
419 "(" +
420 hotMethod.getId() +
421 ")" +
422 " has " +
423 numSamples +
424 " samples");
425 }
426 }
427 }
428
429 ////////////////////////////////////////////////////////////////
430 // Logging level 3
431 ////////////////////////////////////////////////////////////////
432
433 /**
434 * This method logs a controller cost estimate for doing nothing.
435 * @param method the method of interest
436 * @param optLevel the opt level being estimated, -1 = baseline
437 * @param cost the computed cost for this method and level
438 */
439 public void recordControllerEstimateCostDoNothing(RVMMethod method, int optLevel, double cost) {
440 if (Controller.options.LOGGING_LEVEL >= 3) {
441 synchronized (log) {
442 log.print(getTime() + " Estimated cost of doing nothing (leaving at ");
443 if (optLevel == -1) {
444 log.print("baseline");
445 } else {
446 log.print("O" + optLevel);
447 }
448 log.println(") to " + method + " is " + cost);
449 }
450 }
451 }
452
453 /**
454 * This method logs a controller cost estimate.
455 * @param method the method of interest
456 * @param choiceDesc a String describing the choice point
457 * @param compilationTime the computed compilation cost for this method and level
458 * @param futureTime the computed future time, including cost and execution
459 */
460 public void recordControllerEstimateCostOpt(RVMMethod method, String choiceDesc, double compilationTime,
461 double futureTime) {
462 if (Controller.options.LOGGING_LEVEL >= 3) {
463 synchronized (log) {
464 log.println(getTime() +
465 " Estimated cost of OPT compiling " +
466 method +
467 " at " +
468 choiceDesc +
469 " is " +
470 compilationTime +
471 ", total future time is " +
472 futureTime);
473 }
474 }
475 }
476
477 /**
478 * Records lots of details about the online computation of a compilation rate
479 * @param compiler compiler of interest
480 * @param method the method
481 * @param BCLength the number of bytecodes
482 * @param totalBCLength cumulative number of bytecodes
483 * @param MCLength size of machine code
484 * @param totalMCLength cumulative size of machine code
485 * @param compTime compilation time for this method
486 * @param totalCompTime cumulative compilation time for this method
487 * @param totalLogOfRates running sum of the natural logs of the rates
488 * @param totalLogValueMethods number of methods used in the log of rates
489 * @param totalMethods total number of methods
490 */
491 public void recordUpdatedCompilationRates(byte compiler, RVMMethod method, int BCLength, int totalBCLength,
492 int MCLength, int totalMCLength, double compTime,
493 double totalCompTime, double totalLogOfRates,
494 int totalLogValueMethods, int totalMethods) {
495
496 if (Controller.options.LOGGING_LEVEL >= 3) {
497 synchronized (log) {
498 boolean backBranch = false;
499 if (method instanceof NormalMethod) {
500 backBranch = ((NormalMethod) method).hasBackwardsBranch();
501 }
502 log.println(getTime() +
503 " Updated compilation rates for " +
504 RuntimeCompiler.getCompilerName(compiler) +
505 "compiler");
506 log.println("\tmethod compiled: " + method);
507 log.println("\tbyte code length: " + BCLength + ", Total: " + totalBCLength);
508 log.println("\tmachine code length: " + MCLength + ", Total: " + totalMCLength);
509 log.println("\tbackwards branch: " + (backBranch ? "yes" : "no"));
510 log.println("\tcompilation time: " + compTime + ", Total: " + totalCompTime);
511 log.println("\tRate for this method: " + BCLength / compTime + ", Total of Logs: " + totalLogOfRates);
512 log.println("\tTotal Methods: " + totalMethods);
513 log.println("\tNew Rate: " + Math.exp(totalLogOfRates / totalLogValueMethods));
514 }
515 }
516 }
517
518 public void compileAllMethodsCompleted() {
519 if (Controller.options.LOGGING_LEVEL >= 2) {
520 synchronized (log) {
521 log.println(Controller.controllerClock + " Compiled all methods finished. ");
522 }
523 }
524 }
525
526 ////////////////////////////////////////////////////////////////
527 // OSR-related code
528 ////////////////////////////////////////////////////////////////
529
530 /**
531 * This method logs the successful completion of an adaptively
532 * selected recompilation
533 * @param plan the Compilation plan being executed.
534 */
535 public void recordOSRRecompilationDecision(ControllerPlan plan) {
536 CompilationPlan cplan = plan.getCompPlan();
537 if (Controller.options.LOGGING_LEVEL >= 1) {
538 synchronized (log) {
539 log.println(getTime() + " recompile with OSR " + "( at level " + cplan.options.getOptLevel() + " ) " + cplan
540 .method);
541 }
542 }
543 }
544
545 public void onStackReplacementStarted(CompilationPlan plan) {
546 if (Controller.options.LOGGING_LEVEL >= 1) {
547 synchronized (log) {
548 log.println(getTime() + " OSR starts " + "( at level " + plan.options.getOptLevel() + " ) " + plan.method);
549 }
550 }
551 }
552
553 public void onStackReplacementCompleted(CompilationPlan plan) {
554 if (Controller.options.LOGGING_LEVEL >= 1) {
555 synchronized (log) {
556 log.println(getTime() + " OSR ends " + "( at level " + plan.options.getOptLevel() + " ) " + plan.method);
557 }
558 }
559 }
560
561 public void onStackReplacementAborted(CompilationPlan plan) {
562 if (Controller.options.LOGGING_LEVEL >= 1) {
563 synchronized (log) {
564 log.println(getTime() + " OSR failed " + "( at level " + plan.options.getOptLevel() + " ) " + plan.method);
565 }
566 }
567 }
568
569 public void logOsrEvent(String s) {
570 if (Controller.options.LOGGING_LEVEL >= 1) {
571 synchronized (log) {
572 log.println(getTime() + " " + s);
573 }
574 }
575 }
576
577 public void debug(String s) {
578 if (Controller.options.LOGGING_LEVEL >= 2) {
579 synchronized (log) {
580 log.println(getTime() + s);
581 }
582 }
583 }
584 }