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 } |