--- /dev/null 2014-02-13 11:40:26.000000000 -0800 +++ new/modules/base/src/main/java/com/sun/javafx/logging/PrintLogger.java 2014-02-13 11:40:26.220356100 -0800 @@ -0,0 +1,434 @@ +/* + * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. Oracle designates this + * particular file as subject to the "Classpath" exception as provided + * by Oracle in the LICENSE file that accompanied this code. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ + +package com.sun.javafx.logging; + +import java.security.AccessController; +import java.security.PrivilegedAction; +import java.util.ArrayList; +import java.util.Collections; +import java.util.Comparator; +import java.util.List; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicInteger; + +/** + * Logs information on a per-pulse basis. When doing performance analysis, a very + * easy thing to start with is to run with the PulseLogger enabled, such that various + * statistics related to the scene graph and the pulse are recorded and dumped to + * the log. + *

+ * The pulse logger is designed in such a way as to gather all of the pulse statistics + * together even though half of the pulse occurs on the FX thread and half on the + * render thread, and therefore two sets of pulse data are being accumulated + * concurrently. The {@code pulseStart}, {@code pulseEnd}, {@code renderStart}, + * and {@code renderEnd} methods must be called appropriately by the runtime + * to ensure that the logging system works correctly. + */ +class PrintLogger extends Logger { + + /** + * A reference to the pulse logger. This will be null if pulse logging + * is not enabled. + */ + private static PrintLogger printLogger; + + /** + * A time in milliseconds which defines the threshold. If a pulse lasts longer than + * the threshold, then it is logged, otherwise an abbreviated representation including + * only the time of the pulse is logged. + */ + private static long THRESHOLD = (long) + AccessController.doPrivileged(new PrivilegedAction() { + @Override public Integer run() { + return Integer.getInteger("javafx.pulseLogger.threshold", 17); + } + }); + + /** + * Optionally exit after a given number of pulses + */ + private static final int EXIT_ON_PULSE = + AccessController.doPrivileged(new PrivilegedAction() { + @Override + public Integer run() { + return Integer.getInteger("javafx.pulseLogger.exitOnPulse", 0); + } + }); + + /** + * We have a simple counter that keeps track of the current pulse number. + * INTER_PULSE_DATA is used to mark data that comes between pulses. + */ + private int pulseCount = 1; + private static final int INTER_PULSE_DATA = -1; + + /** + * When printing the truncated form of the pulse, we just print one truncated + * form after another, such as: + * + * [5][2][4] + * + * This way we don't cause the console to scroll far vertically in the case of fast + * pulses. We do this so that relevant information (pulses that exceed the threshold) + * is easy to find and remains visible as long as possible in the console. However, + * we don't want to scroll too far off to the right either, so we keep track of + * how many "quick pulses" have happened in a row. When we've exceeded some fixed + * number (20, say) then we will insert a newline into the log. + */ + private volatile int wrapCount = 0; + + /** + * References to PulseData for the FX thread (fxData) and the Render thread (renderData). + */ + private volatile PulseData fxData, renderData; + + /** + * Keeps track of the start of the previous pulse, such that we can print out + * the time interval between the start of pulses. + */ + private long lastPulseStartTime; + + class ThreadLocalData { + String phaseName; + long phaseStart; + } + + private Thread fxThread; + private final ThreadLocal phaseData = + new ThreadLocal() { + @Override + public ThreadLocalData initialValue() { + return new ThreadLocalData(); + } + }; + + + /** + * The queue of all PulseData objects, both available and those in use. + * New PulseData objects are allocated from head if the state is AVAILABLE. + * They are re-linked at tail with the state INCOMPLETE. Once fully processed + * they will change their state back to AVAILABLE and will become ready for reuse. + */ + private PulseData head; + private PulseData tail; + + /** + * A synchronization object for printing arbitrage. + */ + private AtomicInteger active; + + /** + * PulseData object states + */ + private static final int AVAILABLE = 0; + private static final int INCOMPLETE = 1; + private static final int COMPLETE = 2; + + /** + * Disallow instantiation. + */ + private PrintLogger() { + head = new PulseData(); + tail = new PulseData(); + head.next = tail; + active = new AtomicInteger(0); + } + + public static Logger getInstance() { + if (printLogger == null) { + boolean enabled = AccessController.doPrivileged(new PrivilegedAction() { + @Override public Boolean run() { + return Boolean.getBoolean("javafx.pulseLogger"); + } + }); + if (enabled) { + printLogger = new PrintLogger(); + } + } + return printLogger; + } + + /** + * Allocate and initialize a PulseData object + */ + private PulseData allocate(int n) { + PulseData res; + if (head != tail && head.state == AVAILABLE) { + res = head; + head = head.next; + res.next = null; + } + else { + res = new PulseData(); + } + tail.next = res; + tail = res; + res.init(n); + return res; + } + + /** + * MUST be called at the start of every pulse. + * This method will initialize the fxData buffer so that subsequent + * calls to fxMessage will write to this buffer. + */ + @Override + public void pulseStart() { + if (fxThread == null) { + fxThread = Thread.currentThread(); + } + if (fxData != null) { + // Inter pulse data + fxData.state = COMPLETE; + if (active.incrementAndGet() == 1) { + fxData.printAndReset(); + active.decrementAndGet(); + } + } + fxData = allocate(pulseCount++); + if (lastPulseStartTime > 0) { + fxData.interval = (fxData.startTime - lastPulseStartTime)/1000000L; + } + lastPulseStartTime = fxData.startTime; + } + + /** + * Must be called before any set of render jobs + * for a given pulse begin. This method will initialize the + * renderData buffer so that subsequent calls to renderMessage + * will write to this buffer. I have found that sometimes renderMessage + * is called without a pulse being started. Such cases are exceptional + * and appear to happen only at startup, and such cases are simply not + * logged. + */ + @Override + public void renderStart() { + newPhase(null); // finish the current phase on the FX thread + fxData.pushedRender = true; + renderData = fxData; + active.incrementAndGet(); + } + + /** + * Must be called at the end of the pulse. If + * there was no rendering started during this pulse, then this + * method will cause the pulse data to be logged. Otherwise, the + * pulse data is logged when rendering is ended. However, as soon + * as pulseEnd is called, we are ready for another call to pulseStart. + */ + @Override + public void pulseEnd() { + if (!fxData.pushedRender) { + fxData.state = COMPLETE; + if (active.incrementAndGet() == 1) { + fxData.printAndReset(); + active.decrementAndGet(); + } + } + fxData = null; + } + + /** + * Must be called at the end of rendering, if a previous + * call to {@link #renderStart()} had been made. This will cause the pulse + * data to be logged. + */ + @Override + public void renderEnd() { + newPhase(null); // finish the current phase on the render thread + renderData.state = COMPLETE; + for (;;) { + renderData.printAndReset(); + if (active.decrementAndGet() == 0) { + break; + } + renderData = renderData.next; + } + renderData = null; + } + + /** + * Adds a message to the log for the pulse. + * @param message The message to log. A newline will be added automatically. + */ + @Override + public void addMessage(String message) { + PulseData pulseData; + if (fxThread == null || Thread.currentThread() == fxThread) { + if (fxData == null) { + fxData = allocate(INTER_PULSE_DATA); + } + pulseData = fxData; + } + else { + pulseData = renderData; + } + if (pulseData == null) { + return; + } + pulseData.message + .append("T") + .append(Thread.currentThread().getId()) + .append(" : ") + .append(message) + .append("\n"); + } + + /** + * Increments the given named per-pulse counter. + * @param counter The name for the counter. + */ + @Override + public void incrementCounter(String counter) { + PulseData pulseData; + if (fxThread == null || Thread.currentThread() == fxThread) { + if (fxData == null) { + fxData = allocate(INTER_PULSE_DATA); + } + pulseData = fxData; + } + else { + pulseData = renderData; + } + if (pulseData == null) { + return; + } + Map counters = pulseData.counters; + Counter cval = counters.get(counter); + if (cval == null) { + cval = new Counter(); + counters.put(counter, cval); + } + cval.value += 1; + } + + @Override + public void newPhase(String name) { + long curTime = System.nanoTime(); + + ThreadLocalData curPhase = phaseData.get(); + if (curPhase.phaseName != null) { + PulseData pulseData = Thread.currentThread() == fxThread ? fxData : renderData; + if (pulseData != null) { + pulseData.message + .append("T") + .append(Thread.currentThread().getId()) + .append(" (").append((curPhase.phaseStart-pulseData.startTime)/1000000L) + .append(" +").append((curTime - curPhase.phaseStart)/1000000L).append("ms): ") + .append(curPhase.phaseName) + .append("\n"); + } + } + curPhase.phaseName = name; + curPhase.phaseStart = curTime; + } + + /** + * A mutable integer to be used in the counter map + */ + private static class Counter { + int value; + } + + /** + * The data we collect per pulse. We store the pulse number + * associated with this pulse, along with what time it + * started at and the interval since the previous pulse. + * We also maintain the message buffer and counters. + */ + private final class PulseData { + PulseData next; + volatile int state = AVAILABLE; + long startTime; + long interval; + int pulseCount; + boolean pushedRender; + StringBuffer message = new StringBuffer(); + Map counters = new ConcurrentHashMap(); + + void init(int n) { + state = INCOMPLETE; + pulseCount = n; + startTime = System.nanoTime(); + interval = 0; + pushedRender = false; + } + + void printAndReset() { + long endTime = System.nanoTime(); + long totalTime = (endTime - startTime)/1000000L; + + if (state != COMPLETE) { + System.err.println("\nWARNING: logging incomplete state"); + } + + if (totalTime <= THRESHOLD) { + // Don't print inter pulse data + if (pulseCount != INTER_PULSE_DATA) { + System.err.print((wrapCount++ % 10 == 0 ? "\n[" : "[") + pulseCount+ " " + interval + "ms:" + totalTime + "ms]"); + } + } + else { + if (pulseCount == INTER_PULSE_DATA) { + System.err.println("\n\nINTER PULSE LOG DATA"); + } + else { + System.err.print("\n\nPULSE: " + pulseCount + + " [" + interval + "ms:" + totalTime + "ms]"); + if (!pushedRender) { + System.err.print(" Required No Rendering"); + } + System.err.println(); + } + System.err.print(message); + if (!counters.isEmpty()) { + System.err.println("Counters:"); + List> entries = new ArrayList(counters.entrySet()); + Collections.sort(entries, new Comparator>() { + @Override + public int compare(Map.Entry a, Map.Entry b) { + return a.getKey().compareTo(b.getKey()); + } + }); + for (Map.Entry entry : entries) { + System.err.println("\t" + entry.getKey() + ": " + entry.getValue().value); + } + } + wrapCount = 0; + } + + // Reset the state + message.setLength(0); + counters.clear(); + state = AVAILABLE; + if (EXIT_ON_PULSE > 0 && pulseCount >= EXIT_ON_PULSE) { + System.err.println("Exiting after pulse #" + pulseCount); + System.exit(0); + } + } + } +}