modules/base/src/main/java/com/sun/javafx/logging/PulseLogger.java

Print this page


   1 /*
   2  * Copyright (c) 2009, 2013, Oracle and/or its affiliates. All rights reserved.
   3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   4  *
   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.  Oracle designates this
   8  * particular file as subject to the "Classpath" exception as provided
   9  * by Oracle in the LICENSE file that accompanied this code.
  10  *
  11  * This code is distributed in the hope that it will be useful, but WITHOUT
  12  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  14  * version 2 for more details (a copy is included in the LICENSE file that
  15  * accompanied this code).
  16  *
  17  * You should have received a copy of the GNU General Public License version
  18  * 2 along with this work; if not, write to the Free Software Foundation,
  19  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  20  *
  21  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  22  * or visit www.oracle.com if you need additional information or have any
  23  * questions.
  24  */
  25 
  26 package com.sun.javafx.logging;
  27 
  28 import java.security.AccessController;
  29 import java.security.PrivilegedAction;
  30 import java.util.ArrayList;
  31 import java.util.Collections;
  32 import java.util.Comparator;
  33 import java.util.List;
  34 import java.util.Map;
  35 import java.util.concurrent.ConcurrentHashMap;
  36 import java.util.concurrent.atomic.AtomicInteger;
  37 
  38 /**
  39  * Logs information on a per-pulse basis. When doing performance analysis, a very
  40  * easy thing to start with is to run with the PulseLogger enabled, such that various
  41  * statistics related to the scene graph and the pulse are recorded and dumped to
  42  * the log.
  43  * <p>
  44  * The pulse logger is designed in such a way as to gather all of the pulse statistics
  45  * together even though half of the pulse occurs on the FX thread and half on the
  46  * render thread, and therefore two sets of pulse data are being accumulated
  47  * concurrently. The {@code pulseStart}, {@code pulseEnd}, {@code renderStart},
  48  * and {@code renderEnd} methods must be called appropriately by the runtime
  49  * to ensure that the logging system works correctly.
  50  */
  51 public class PulseLogger {
  52     /**
  53      * Specifies whether pulse logging is enabled or not. This is set via
  54      * a command line flag and defaults to false.
  55      */
  56     public static final boolean PULSE_LOGGING_ENABLED =
  57             AccessController.doPrivileged(new PrivilegedAction<Boolean>() {
  58                 @Override public Boolean run() {
  59                     return Boolean.getBoolean("javafx.pulseLogger");
  60                 }
  61             });
  62 
  63     /**
  64      * A reference to the pulse logger. This will be null if pulse logging
  65      * is not enabled.
  66      */
  67     public static final PulseLogger PULSE_LOGGER = PULSE_LOGGING_ENABLED ? new PulseLogger() : null;
  68 
  69     /**
  70      * A time in milliseconds which defines the threshold. If a pulse lasts <em>longer</em> than
  71      * the threshold, then it is logged, otherwise an abbreviated representation including
  72      * only the time of the pulse is logged.
  73      */
  74     private static long THRESHOLD = (long)
  75             AccessController.doPrivileged(new PrivilegedAction<Integer>() {
  76                 @Override public Integer run() {
  77                     return Integer.getInteger("javafx.pulseLogger.threshold", 17);
  78                 }
  79             });
  80 
  81     /**
  82      * Optionally exit after a given number of pulses
  83      */
  84     private static final int EXIT_ON_PULSE =
  85             AccessController.doPrivileged(new PrivilegedAction<Integer>() {
  86                 @Override
  87                 public Integer run() {
  88                     return Integer.getInteger("javafx.pulseLogger.exitOnPulse", 0);
  89                 }
  90             });
  91 
  92     /**
  93      * We have a simple counter that keeps track of the current pulse number.
  94      * INTER_PULSE_DATA is used to mark data that comes between pulses.
  95      */
  96     private int pulseCount = 1;
  97     private static final int INTER_PULSE_DATA = -1;
  98 
  99     /**
 100      * When printing the truncated form of the pulse, we just print one truncated
 101      * form after another, such as:
 102      * 
 103      * [5][2][4]
 104      * 
 105      * This way we don't cause the console to scroll far vertically in the case of fast
 106      * pulses. We do this so that relevant information (pulses that exceed the threshold)
 107      * is easy to find and remains visible as long as possible in the console. However,
 108      * we don't want to scroll too far off to the right either, so we keep track of
 109      * how many "quick pulses" have happened in a row. When we've exceeded some fixed
 110      * number (20, say) then we will insert a newline into the log.
 111      */
 112     private volatile int wrapCount = 0;
 113 
 114     /**
 115      * References to PulseData for the FX thread (fxData) and the Render thread (renderData).
 116      */
 117     private volatile PulseData fxData, renderData;
 118 
 119     /**
 120      * Keeps track of the start of the previous pulse, such that we can print out
 121      * the time interval between the start of pulses.
 122      */
 123     private long lastPulseStartTime;
 124 
 125     /**
 126      * No logger activity is expected outside the renderStart..renderEnd interval.
 127      * This flag is for notification when that assumption is broken.
 128      */
 129     private boolean nullRenderFlag = false;
 130 
 131     /**
 132      * The queue of all PulseData objects, both available and those in use.
 133      * New PulseData objects are allocated from head if the state is AVAILABLE.
 134      * They are re-linked at tail with the state INCOMPLETE. Once fully processed
 135      * they will change their state back to AVAILABLE and will become ready for reuse.
 136      */
 137     private PulseData head;
 138     private PulseData tail;
 139     
 140     /**
 141      * A synchronization object for printing arbitrage.
 142      */
 143     AtomicInteger active = new AtomicInteger(0);
 144     
 145     /**
 146      * PulseData object states
 147      */
 148     private static final int AVAILABLE = 0;
 149     private static final int INCOMPLETE = 1;
 150     private static final int COMPLETE = 2;
 151     
 152     /**
 153      * Disallow instantiation.
 154      */
 155     private PulseLogger() {
 156         head = new PulseData();
 157         tail = new PulseData();
 158         head.next = tail;
 159     }
 160 
 161     /**
 162      * Allocate and initialize a PulseData object
 163      */
 164     private PulseData allocate(int n) {
 165         PulseData res;
 166         if (head != tail && head.state == AVAILABLE) {
 167             res = head;
 168             head = head.next;
 169             res.next = null;
 170         }
 171         else {
 172             res = new PulseData();
 173         }
 174         tail.next = res;
 175         tail = res;
 176         res.init(n);        
 177         return res;
 178     }
 179 
 180     /**
 181      * <strong>MUST</strong> be called at the start of every pulse.
 182      * This method will initialize the fxData buffer so that subsequent
 183      * calls to fxMessage will write to this buffer.
 184      */
 185     public void pulseStart() {
 186         if (fxData != null) {
 187             // Inter pulse data
 188             fxData.state = COMPLETE;
 189             if (active.incrementAndGet() == 1) {
 190                 fxData.printAndReset();
 191                 active.decrementAndGet();
 192             }
 193         }
 194         fxData = allocate(pulseCount++);
 195         if (lastPulseStartTime > 0) {
 196             fxData.interval = fxData.startTime - lastPulseStartTime;
 197         }
 198         lastPulseStartTime = fxData.startTime;
 199     }
 200 
 201     /**
 202      * <strong>Must</strong> be called before any set of render jobs
 203      * for a given pulse begin. This method will initialize the
 204      * renderData buffer so that subsequent calls to renderMessage
 205      * will write to this buffer. I have found that sometimes renderMessage
 206      * is called without a pulse being started. Such cases are exceptional
 207      * and appear to happen only at startup, and such cases are simply not
 208      * logged.
 209      */
 210     public void renderStart() {
 211         fxData.pushedRender = true;
 212         renderData = fxData;
 213         active.incrementAndGet();
 214     }
 215 
 216     /**
 217      * <strong>Must</strong> be called at the end of the pulse. If
 218      * there was no rendering started during this pulse, then this
 219      * method will cause the pulse data to be logged. Otherwise, the
 220      * pulse data is logged when rendering is ended. However, as soon
 221      * as pulseEnd is called, we are ready for another call to pulseStart.
 222      */
 223     public void pulseEnd() {
 224         if (!fxData.pushedRender) {
 225             fxData.state = COMPLETE;
 226             if (active.incrementAndGet() == 1) {
 227                 fxData.printAndReset();
 228                 active.decrementAndGet();
 229             }




 230         }
 231         fxData = null;
 232     }
 233 
 234     /**
 235      * <strong>Must</strong> be called at the end of rendering, if a previous
 236      * call to {@link #renderStart()} had been made. This will cause the pulse
 237      * data to be logged.
 238      */
 239     public void renderEnd() {
 240         renderData.state = COMPLETE;
 241         for (;;) {
 242             renderData.printAndReset();
 243             if (active.decrementAndGet() == 0) {
 244                 break;
 245             }
 246             renderData = renderData.next;
 247         }
 248         renderData = null;




 249     }
 250 
 251     /**
 252      * Adds a message to the log for the pulse. This method <strong>MUST ONLY
 253      * BE CALLED FROM THE FX THREAD</strong>.
 254      * 
 255      * @param message The message to log. A newline will be added automatically.
 256      */
 257     public void fxMessage(String message) {
 258         if (fxData == null) {
 259             fxData = allocate(INTER_PULSE_DATA);
 260         }
 261         fxData.message
 262             .append("T")
 263             .append(Thread.currentThread().getId())
 264             .append(" : ")
 265             .append(message)
 266             .append("\n");
 267     }
 268 
 269     /**
 270      * Adds a timing message to the log for the pulse. This method <strong>MUST ONLY
 271      * BE CALLED FROM THE FX THREAD</strong>. The milliseconds will be computed and
 272      * added to the message. A newline will be added to the message.
 273      * <p>
 274      * This is typically used as follows:
 275      * 
 276      * long start = PULSE_LOGGING_ENABLED ? System.currentTimeMillis() : 0;
 277      * operationToBeTimed();
 278      * if (PULSE_LOGGING_ENABLED) {
 279      *     PULSE_LOGGER.fxMessage(start, System.currentTimeMillis(), "Operation Identifier");
 280      * }
 281      * 
 282      * @param start The time in milliseconds when this operation started
 283      * @param end The time in milliseconds when the operation ended
 284      * @param message The message to log. A newline will be added automatically.
 285      */
 286     public void fxMessage(long start, long end, String message) {
 287         if (fxData == null) {
 288             fxData = allocate(INTER_PULSE_DATA);
 289         }
 290         fxData.message
 291             .append("T")
 292             .append(Thread.currentThread().getId())
 293             .append(" (").append(start-fxData.startTime).append(" +").append(end - start).append("ms): ")
 294             .append(message)
 295             .append("\n");
 296     }
 297 
 298     /**
 299      * Increments the given named per-pulse counter. This method <strong>MUST
 300      * ONLY BE CALLED ON THE FX THREAD</strong>.
 301      * @param counter The name for the counter.
 302      */
 303     public void fxIncrementCounter(String counter) {
 304         if (fxData == null) {
 305             fxData = allocate(INTER_PULSE_DATA);
 306         }
 307         Map<String,Integer> counters = fxData.counters;
 308         if (counters.containsKey(counter)) {
 309             counters.put(counter, counters.get(counter) + 1);
 310         } else {
 311             counters.put(counter, 1);
 312         }
 313     }
 314     
 315     /**
 316      * Adds a message to the log for the pulse. This method <strong>MUST ONLY
 317      * BE CALLED FROM THE RENDER THREAD</strong>.
 318      * 
 319      * @param message The message to log. A newline will be added automatically.
 320      */
 321     public void renderMessage(String message) {
 322         if (renderData == null) {
 323             nullRenderFlag = true;
 324             return;
 325         }
 326         renderData.message
 327             .append("T")
 328             .append(Thread.currentThread().getId())
 329             .append(" : ")
 330             .append(message)
 331             .append("\n");
 332     }
 333 
 334     /**
 335      * Adds a timing message to the log for the pulse. This method <strong>MUST ONLY
 336      * BE CALLED FROM THE RENDER THREAD</strong>. The milliseconds will be computed and
 337      * added to the message. A newline will be added to the message.
 338      * <p>
 339      * This is typically used as follows:
 340      * 
 341      * long start = PULSE_LOGGING_ENABLED ? System.currentTimeMillis() : 0;
 342      * operationToBeTimed();
 343      * if (PULSE_LOGGING_ENABLED) {
 344      *     PULSE_LOGGER.renderMessage(start, System.currentTimeMillis(), "Operation Identifier");
 345      * }
 346      * 
 347      * @param start The time in milliseconds when this operation started
 348      * @param end The time in milliseconds when the operation ended
 349      * @param message The message to log. A newline will be added automatically.
 350      */
 351     public void renderMessage(long start, long end, String message) {
 352         if (renderData == null) {
 353             nullRenderFlag = true;
 354             return;
 355         }
 356         renderData.message
 357             .append("T")
 358             .append(Thread.currentThread().getId())
 359             .append(" (").append(start-renderData.startTime).append(" +").append(end - start).append("ms): ")
 360             .append(message)
 361             .append("\n");
 362     }
 363 
 364     /**
 365      * Increments the given named per-pulse counter. This method <strong>MUST
 366      * ONLY BE CALLED ON THE RENDER THREAD</strong>.
 367      * @param counter The name for the counter.
 368      */
 369     public void renderIncrementCounter(String counter) {
 370         if (renderData == null) {
 371             nullRenderFlag = true;
 372             return;
 373         }
 374         Map<String,Integer> counters = renderData.counters;
 375         if (counters.containsKey(counter)) {
 376             counters.put(counter, counters.get(counter) + 1);
 377         } else {
 378             counters.put(counter, 1);
 379         }
 380     }
 381     
 382     /**
 383      * The data we collect per pulse. We store the pulse number
 384      * associated with this pulse, along with what time it
 385      * started at and the interval since the previous pulse.
 386      * We also maintain the message buffer and counters.
 387      */
 388     private final class PulseData {
 389         PulseData next;
 390         volatile int state = AVAILABLE;
 391         long startTime;
 392         long interval;
 393         int pulseCount;
 394         boolean pushedRender;
 395         StringBuffer message = new StringBuffer();
 396         Map<String,Integer> counters = new ConcurrentHashMap<String, Integer>();
 397 
 398         void init(int n) {
 399             state = INCOMPLETE;
 400             pulseCount = n;
 401             startTime = System.currentTimeMillis();
 402             interval = 0;
 403             pushedRender = false;
 404         }
 405         
 406         void printAndReset() {
 407             long endTime = System.currentTimeMillis();
 408             long totalTime = endTime - startTime;
 409             
 410             if (nullRenderFlag) {
 411                 System.err.println("\nWARNING: unexpected render thread activity");
 412                 nullRenderFlag = false;
 413             }
 414             if (state != COMPLETE) {
 415                 System.err.println("\nWARNING: logging incomplete state");
 416             }
 417             
 418             if (totalTime <= THRESHOLD) {
 419                 // Don't print inter pulse data
 420                 if (pulseCount != INTER_PULSE_DATA) {
 421                     System.err.print((wrapCount++ % 10 == 0 ? "\n[" : "[") + pulseCount+ " " + interval + "ms:" + totalTime + "ms]");
 422                 }
 423             }
 424             else {
 425                 if (pulseCount == INTER_PULSE_DATA) {
 426                     System.err.println("\n\nINTER PULSE LOG DATA");                
 427                 }
 428                 else {
 429                     System.err.print("\n\nPULSE: " + pulseCount +
 430                             " [" + interval + "ms:" + totalTime + "ms]");
 431                     if (!pushedRender) {
 432                         System.err.print(" Required No Rendering");
 433                     }
 434                     System.err.println();
 435                 }
 436                 System.err.print(message);
 437                 if (!counters.isEmpty()) {
 438                     System.err.println("Counters:");
 439                     List<Map.Entry<String,Integer>> entries = new ArrayList<Map.Entry<String,Integer>>(counters.entrySet());
 440                     Collections.sort(entries, new Comparator<Map.Entry<String,Integer>>() {
 441                         public int compare(Map.Entry<String,Integer> a, Map.Entry<String,Integer> b) {
 442                             return a.getKey().compareTo(b.getKey());
 443                         }
 444                     });
 445                     for (Map.Entry<String, Integer> entry : entries) {
 446                         System.err.println("\t" + entry.getKey() + ": " + entry.getValue());
 447                     }
 448                 }
 449                 wrapCount = 0;
 450             }
 451             
 452             // Reset the state
 453             message.setLength(0);
 454             counters.clear();
 455             state = AVAILABLE;
 456             if (EXIT_ON_PULSE > 0 && pulseCount >= EXIT_ON_PULSE) {
 457                 System.err.println("Exiting after pulse #" + pulseCount);
 458                 System.exit(0);
 459             }




 460         }
 461     }
 462 }
   1 /*
   2  * Copyright (c) 2009, 2014, Oracle and/or its affiliates. All rights reserved.
   3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   4  *
   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.  Oracle designates this
   8  * particular file as subject to the "Classpath" exception as provided
   9  * by Oracle in the LICENSE file that accompanied this code.
  10  *
  11  * This code is distributed in the hope that it will be useful, but WITHOUT
  12  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  13  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  14  * version 2 for more details (a copy is included in the LICENSE file that
  15  * accompanied this code).
  16  *
  17  * You should have received a copy of the GNU General Public License version
  18  * 2 along with this work; if not, write to the Free Software Foundation,
  19  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  20  *
  21  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  22  * or visit www.oracle.com if you need additional information or have any
  23  * questions.
  24  */
  25 
  26 package com.sun.javafx.logging;
  27 


  28 import java.util.ArrayList;


  29 import java.util.List;
































































































  30 
  31 public class PulseLogger {







  32     
  33     public static final boolean PULSE_LOGGING_ENABLED;



  34     
  35     private static final Logger[] loggers;





  36     
  37     static {
  38         List<Logger> list = new ArrayList();
  39         Logger logger = PrintLogger.getInstance();
  40         if (logger != null) {
  41             list.add(logger);


  42         }
  43         logger = JFRLogger.getInstance();
  44         if (logger != null) {
  45             list.add(logger);



















































  46         }
  47         loggers = list.toArray(new Logger[list.size()]);
  48         PULSE_LOGGING_ENABLED = loggers.length > 0;












  49     }
  50     
  51     public static void pulseStart() {
  52         for (Logger logger: loggers) {
  53             logger.pulseStart();
  54         }

  55     }
  56     
  57     public static void pulseEnd() {
  58         for (Logger logger: loggers) {
  59             logger.pulseEnd();








  60         }

  61     }
  62 
  63     public static void renderStart() {
  64         for (Logger logger: loggers) {
  65             logger.renderStart();
  66         }
  67     }
  68     
  69     public static void renderEnd() {
  70         for (Logger logger: loggers) {
  71             logger.renderEnd();




















































  72         }
  73     }
  74     
  75     public static void addMessage(String message) {
  76         for (Logger logger: loggers) {
  77             logger.addMessage(message);
  78         }
  79     }
  80         
  81     public static void incrementCounter(String counter) {
  82         for (Logger logger: loggers) {
  83             logger.incrementCounter(counter);





























































  84         }
  85     }
  86     
  87     public static void newPhase(String name) {
  88         for (Logger logger: loggers) {
  89             logger.newPhase(name);
  90         }









































































  91     }
  92 
  93     public static void newInput(String name) {
  94         for (Logger logger: loggers) {
  95             logger.newInput(name);
  96         }
  97     }
  98 }