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