| // Copyright (c) 2011, the Dart project authors. Please see the AUTHORS file |
| // for details. All rights reserved. Use of this source code is governed by a |
| // BSD-style license that can be found in the LICENSE file. |
| |
| package com.google.dart.compiler.metrics; |
| |
| import org.json.JSONException; |
| import org.json.JSONObject; |
| import org.json.JSONArray; |
| |
| import java.io.BufferedWriter; |
| import java.io.FileWriter; |
| import java.io.IOException; |
| import java.io.Writer; |
| import java.lang.management.GarbageCollectorMXBean; |
| import java.lang.management.ManagementFactory; |
| import java.lang.management.OperatingSystemMXBean; |
| import java.lang.management.ThreadMXBean; |
| import java.lang.reflect.Method; |
| import java.util.ArrayList; |
| import java.util.Arrays; |
| import java.util.List; |
| import java.util.Map; |
| import java.util.Stack; |
| import java.util.concurrent.BlockingQueue; |
| import java.util.concurrent.ConcurrentHashMap; |
| import java.util.concurrent.CountDownLatch; |
| import java.util.concurrent.LinkedBlockingQueue; |
| import java.util.concurrent.TimeUnit; |
| |
| /** |
| * Logs performance metrics for internal development purposes. The output is |
| * formatted so it can be opened directly in the SpeedTracer Chrome extension. |
| * This class formats events using SpeedTracer's custom event feature. The html |
| * file output can be viewed by using Chrome to open the file on a Chrome |
| * browser that has the SpeedTracer extension installed. |
| * |
| * <p> |
| * Enable logging by setting the system property {@code dart.speedtracerlog} to |
| * the output file path. |
| * </p> |
| * |
| * NB: This class has been copied almost verbatim from the gwt source tree |
| */ |
| public final class Tracer { |
| |
| // Log file name (logging is enabled if this is non-null) |
| private static final String logFile = System.getProperty("dart.speedtracerlog"); |
| |
| // Allow a system property to override the default output format |
| private static final String defaultFormatString = System.getProperty("dart.speedtracerformat"); |
| |
| // Use cumulative multi-threaded process cpu time instead of wall time |
| private static final boolean logProcessCpuTime = |
| getBooleanProperty("dart.speedtracer.logProcessCpuTime"); |
| |
| // Use per thread cpu time instead of wall time. If logProcessCpuTime is set, |
| // then this can remain false - we only need one or the other. |
| private static final boolean logThreadCpuTime = |
| getBooleanProperty("dart.speedtracer.logThreadCpuTime"); |
| |
| // Turn on logging summarizing gc time during an event |
| private static final boolean logGcTime = getBooleanProperty("dart.speedtracer.logGcTime"); |
| |
| // Turn on logging estimating overhead used for speedtracer logging. |
| private static final boolean logOverheadTime = |
| getBooleanProperty("dart.speedtracer.logOverheadTime"); |
| |
| static { |
| // verify configuration |
| if (logProcessCpuTime && logThreadCpuTime) { |
| throw new RuntimeException("System properties are misconfigured: " |
| + "Specify one or the other of 'dart.speedtracer.logProcessCpuTime' " |
| + "or 'dart.speedtracer.logThreadCpuTime', not both."); |
| } |
| } |
| |
| /** |
| * Represents a node in a tree of SpeedTracer events. |
| */ |
| public class TraceEvent { |
| protected final EventType type; |
| List<TraceEvent> children; |
| List<String> data; |
| |
| long elapsedDurationNanos; |
| long elapsedStartTimeNanos; |
| |
| long processCpuDurationNanos; |
| long processCpuStartTimeNanos; |
| |
| long threadCpuDurationNanos; |
| long threadCpuStartTimeNanos; |
| |
| TraceEvent() { |
| if (enabled) { |
| threadCpuTimeKeeper.resetTimeBase(); |
| recordStartTime(); |
| this.data = new ArrayList<String>(); |
| this.children = new ArrayList<TraceEvent>(); |
| } else { |
| this.processCpuStartTimeNanos = 0L; |
| this.threadCpuStartTimeNanos = 0L; |
| this.elapsedStartTimeNanos = 0L; |
| this.data = null; |
| this.children = null; |
| } |
| this.type = null; |
| } |
| |
| TraceEvent(TraceEvent parent, EventType type, String... data) { |
| |
| if (parent != null) { |
| parent.children.add(this); |
| } |
| this.type = type; |
| assert (data.length % 2 == 0); |
| recordStartTime(); |
| this.data = new ArrayList<String>(); |
| this.data.addAll(Arrays.asList(data)); |
| this.children = new ArrayList<TraceEvent>(); |
| } |
| |
| /** |
| * @param data key/value pairs to add to JSON object. |
| */ |
| public void addData(String... data) { |
| if (data != null) { |
| assert (data.length % 2 == 0); |
| this.data.addAll(Arrays.asList(data)); |
| } |
| } |
| |
| /** |
| * Signals the end of the current event. |
| */ |
| public void end(String... data) { |
| endImpl(this, data); |
| } |
| |
| /** |
| * Returns the event duration, in nanoseconds, for the log file. Depending |
| * on system properties, this will measured in elapsed time, process CPU |
| * time, or thread CPU time. |
| */ |
| public long getDurationNanos() { |
| return logProcessCpuTime ? processCpuDurationNanos : (logThreadCpuTime |
| ? threadCpuDurationNanos : elapsedDurationNanos); |
| } |
| |
| public long getElapsedDurationNanos() { |
| return this.elapsedDurationNanos; |
| } |
| |
| public long getElapsedStartTimeNanos() { |
| return this.elapsedStartTimeNanos; |
| } |
| |
| /** |
| * Returns the event start time, normalized in nanoseconds, for the log |
| * file. Depending on system properties, this will be normalized based on |
| * elapsed time, process CPU time, or thread CPU time. |
| */ |
| public long getStartTimeNanos() { |
| return logProcessCpuTime ? processCpuStartTimeNanos : (logThreadCpuTime |
| ? threadCpuStartTimeNanos : elapsedStartTimeNanos); |
| } |
| |
| public EventType getType() { |
| return type; |
| } |
| |
| @Override |
| public String toString() { |
| return type.getName(); |
| } |
| |
| /** |
| * Extends the durations of the current event by the durations of the |
| * specified event. |
| */ |
| void extendDuration(TraceEvent refEvent) { |
| elapsedDurationNanos += refEvent.elapsedDurationNanos; |
| processCpuDurationNanos += refEvent.processCpuDurationNanos; |
| threadCpuDurationNanos += refEvent.threadCpuDurationNanos; |
| } |
| |
| /** |
| * Sets the start time of this event to start immediately after the |
| * specified event ends. |
| */ |
| void setStartsAfter(TraceEvent refEvent) { |
| elapsedStartTimeNanos = refEvent.elapsedStartTimeNanos + refEvent.elapsedDurationNanos; |
| processCpuStartTimeNanos = |
| refEvent.processCpuStartTimeNanos + refEvent.processCpuDurationNanos; |
| threadCpuStartTimeNanos = refEvent.threadCpuStartTimeNanos + refEvent.threadCpuDurationNanos; |
| } |
| |
| JSONObject toJson() throws JSONException { |
| JSONObject json = new JSONObject(); |
| json.put("type", -2); |
| json.put("typeName", type.getName()); |
| json.put("color", type.getColor()); |
| double startMs = convertToMilliseconds(getStartTimeNanos()); |
| json.put("time", startMs); |
| double durationMs = convertToMilliseconds(getDurationNanos()); |
| json.put("duration", durationMs); |
| |
| JSONObject jsonData = new JSONObject(); |
| for (int i = 0; i < data.size(); i += 2) { |
| jsonData.put(data.get(i), data.get(i + 1)); |
| } |
| json.put("data", jsonData); |
| |
| JSONArray jsonChildren = new JSONArray(); |
| for (TraceEvent child : children) { |
| jsonChildren.put(child.toJson()); |
| } |
| json.put("children", jsonChildren); |
| |
| return json; |
| } |
| |
| /** |
| * Records the duration of this event based on the current time and the |
| * event's recorded start time. |
| */ |
| void updateDuration() { |
| long elapsedEndTimeNanos = elapsedTimeKeeper.normalizedTimeNanos(); |
| assert (elapsedEndTimeNanos >= elapsedStartTimeNanos); |
| elapsedDurationNanos = elapsedEndTimeNanos - elapsedStartTimeNanos; |
| |
| // don't bother making expensive time keeping method calls unless |
| // necessary |
| if (logProcessCpuTime) { |
| long processCpuEndTimeNanos = processCpuTimeKeeper.normalizedTimeNanos(); |
| assert (processCpuEndTimeNanos >= processCpuStartTimeNanos); |
| processCpuDurationNanos = processCpuEndTimeNanos - processCpuStartTimeNanos; |
| } else if (logThreadCpuTime) { |
| long threadCpuEndTimeNanos = threadCpuTimeKeeper.normalizedTimeNanos(); |
| assert (threadCpuEndTimeNanos >= threadCpuStartTimeNanos); |
| threadCpuDurationNanos = threadCpuEndTimeNanos - threadCpuStartTimeNanos; |
| } |
| } |
| |
| /** |
| * Marks the start time for this event. Three different time measurements |
| * are used: |
| * <ol> |
| * <li>Elapsed (wall-clock) time</li> |
| * <li>Process CPU time</li> |
| * <li>Thread CPU time</li> |
| * </ol> |
| */ |
| private void recordStartTime() { |
| elapsedStartTimeNanos = elapsedTimeKeeper.normalizedTimeNanos(); |
| |
| // don't bother making expensive time keeping method calls unless |
| // necessary |
| if (logProcessCpuTime) { |
| processCpuStartTimeNanos = processCpuTimeKeeper.normalizedTimeNanos(); |
| } else if (logThreadCpuTime) { |
| threadCpuStartTimeNanos = threadCpuTimeKeeper.normalizedTimeNanos(); |
| } |
| } |
| } |
| |
| /** |
| * Enumerated types for logging events implement this interface. |
| */ |
| public interface EventType { |
| String getColor(); |
| |
| String getName(); |
| } |
| |
| static enum Format { |
| /** |
| * Standard SpeedTracer log that includes JSON wrapped in HTML that will |
| * launch a SpeedTracer monitor session. |
| */ |
| HTML, |
| |
| /** |
| * Only the JSON data without any HTML wrappers. |
| */ |
| RAW |
| } |
| |
| /** |
| * A dummy implementation to do nothing if logging has not been turned on. |
| */ |
| private class DummyEvent extends TraceEvent { |
| @Override |
| public void addData(String... data) { |
| // do nothing |
| } |
| |
| @Override |
| public void end(String... data) { |
| // do nothing |
| } |
| |
| @Override |
| public String toString() { |
| return "Dummy"; |
| } |
| } |
| |
| /** |
| * Provides functionality specific to garbage collection events. |
| */ |
| private class GcEvent extends TraceEvent { |
| private TraceEvent refEvent; |
| |
| /** |
| * Constructs an event that represents garbage collection metrics. |
| * |
| * @param refEvent the event during which the garbage collections took place |
| * @param gcType the garbage collector type |
| * @param collectionCount the total number of collections for this garbage |
| * collector type |
| * @param durationNanos the total elapsed time spent in garbage collection |
| * during the span of {@code refEvent} |
| */ |
| GcEvent(TraceEvent refEvent, String gcType, long collectionCount, long durationNanos) { |
| super(null, SpeedTracerEventType.GC, "Collector Type", gcType, "Cumulative Collection Count", |
| Long.toString(collectionCount)); |
| |
| this.refEvent = refEvent; |
| // GarbageCollectorMXBean can only provide elapsed time, so that's all we |
| // record |
| this.elapsedDurationNanos = durationNanos; |
| } |
| |
| /** |
| * Returns elapsed duration since that is the only duration we can measure |
| * for garbage collection events. |
| */ |
| @Override |
| public long getDurationNanos() { |
| return getElapsedDurationNanos(); |
| } |
| |
| /** |
| * Returns a start time so that this event ends with its {@code refEvent}. |
| */ |
| @Override |
| public long getElapsedStartTimeNanos() { |
| return refEvent.getElapsedStartTimeNanos() + refEvent.getElapsedDurationNanos() |
| - getElapsedDurationNanos(); |
| } |
| |
| /** |
| * Returns a start time so that this event ends with its {@code refEvent}. |
| */ |
| @Override |
| public long getStartTimeNanos() { |
| return refEvent.getStartTimeNanos() + refEvent.getDurationNanos() - getDurationNanos(); |
| } |
| } |
| |
| /** |
| * Time keeper which uses wall time. |
| */ |
| private class ElapsedNormalizedTimeKeeper { |
| |
| private final long zeroTimeMillis; |
| |
| public ElapsedNormalizedTimeKeeper() { |
| zeroTimeMillis = System.currentTimeMillis(); |
| } |
| |
| public long normalizedTimeNanos() { |
| return (System.currentTimeMillis() - zeroTimeMillis) * 1000000L; |
| } |
| |
| public long zeroTimeMillis() { |
| return zeroTimeMillis; |
| } |
| } |
| |
| /** |
| * Time keeper which uses process cpu time. This can be greater than wall |
| * time, since it is cumulative over the multiple threads of a process. |
| */ |
| private class ProcessNormalizedTimeKeeper { |
| private final OperatingSystemMXBean osMXBean; |
| private final Method getProcessCpuTimeMethod; |
| private final long zeroTimeNanos; |
| private final long zeroTimeMillis; |
| |
| public ProcessNormalizedTimeKeeper() { |
| try { |
| osMXBean = ManagementFactory.getOperatingSystemMXBean(); |
| /* |
| * Find this method by reflection, since it's part of the Sun |
| * implementation for OperatingSystemMXBean, and we can't always assume |
| * that com.sun.management.OperatingSystemMXBean will be available. |
| */ |
| getProcessCpuTimeMethod = osMXBean.getClass().getMethod("getProcessCpuTime"); |
| getProcessCpuTimeMethod.setAccessible(true); |
| zeroTimeNanos = (Long) getProcessCpuTimeMethod.invoke(osMXBean); |
| zeroTimeMillis = (long) convertToMilliseconds(zeroTimeNanos); |
| } catch (Exception ex) { |
| throw new RuntimeException(ex); |
| } |
| } |
| |
| public long normalizedTimeNanos() { |
| try { |
| return (Long) getProcessCpuTimeMethod.invoke(osMXBean) - zeroTimeNanos; |
| } catch (Exception ex) { |
| throw new RuntimeException(ex); |
| } |
| } |
| |
| public long zeroTimeMillis() { |
| return zeroTimeMillis; |
| } |
| } |
| |
| /** |
| * Time keeper which uses per thread cpu time. It is assumed that individual |
| * events logged will be single threaded, and that top-level events will call |
| * {@link #resetTimeBase()} prior to logging time. The resettable time base is |
| * needed since each individual thread starts its timing at 0, regardless of |
| * when the thread is created. So we reset the time base at the beginning of |
| * an event, so that we can generate a chronologically representative output, |
| * although the relation to wall time is actually compressed within a logged |
| * event (thread cpu time does not include wait time, etc.). |
| */ |
| private class ThreadNormalizedTimeKeeper { |
| |
| private final ThreadMXBean threadMXBean; |
| private final ThreadLocal<Long> resettableTimeBase = new ThreadLocal<Long>(); |
| private final long zeroTimeNanos; |
| private final long zeroTimeMillis; |
| |
| public ThreadNormalizedTimeKeeper() { |
| threadMXBean = ManagementFactory.getThreadMXBean(); |
| if (!threadMXBean.isCurrentThreadCpuTimeSupported()) { |
| throw new RuntimeException("Current thread cpu time not supported"); |
| } |
| zeroTimeNanos = System.nanoTime(); |
| zeroTimeMillis = (long) convertToMilliseconds(zeroTimeNanos); |
| } |
| |
| public long normalizedTimeNanos() { |
| return threadMXBean.getCurrentThreadCpuTime() + resettableTimeBase.get(); |
| } |
| |
| public void resetTimeBase() { |
| /* |
| * Since all threads start individually at time 0L, we use this to offset |
| * each event's time so we can generate chronological output. |
| */ |
| resettableTimeBase.set(System.nanoTime() - zeroTimeNanos |
| - threadMXBean.getCurrentThreadCpuTime()); |
| } |
| |
| public long zeroTimeMillis() { |
| return zeroTimeMillis; |
| } |
| } |
| |
| /** |
| * Initializes the singleton on demand. |
| */ |
| private static class LazySpeedTracerLoggerHolder { |
| public static Tracer singleton = new Tracer(); |
| } |
| |
| /** |
| * Thread that converts log requests to JSON in the background. |
| */ |
| private class LogWriterThread extends Thread { |
| private static final int FLUSH_TIMER_MSECS = 10000; |
| private final String fileName; |
| private final BlockingQueue<TraceEvent> threadEventQueue; |
| private final Writer writer; |
| |
| public LogWriterThread(Writer writer, String fileName, final BlockingQueue<TraceEvent> eventQueue) { |
| super(); |
| this.writer = writer; |
| this.fileName = fileName; |
| this.threadEventQueue = eventQueue; |
| } |
| |
| @Override |
| public void run() { |
| long nextFlush = System.currentTimeMillis() + FLUSH_TIMER_MSECS; |
| try { |
| while (true) { |
| TraceEvent event = |
| threadEventQueue.poll(nextFlush - System.currentTimeMillis(), TimeUnit.MILLISECONDS); |
| if (event == null) { |
| // ignore. |
| } else if (event == shutDownSentinel) { |
| break; |
| } else if (event == flushSentinel) { |
| writer.flush(); |
| flushLatch.countDown(); |
| } else { |
| JSONObject json = event.toJson(); |
| json.write(writer); |
| writer.write('\n'); |
| } |
| if (System.currentTimeMillis() >= nextFlush) { |
| writer.flush(); |
| nextFlush = System.currentTimeMillis() + FLUSH_TIMER_MSECS; |
| } |
| } |
| // All queued events have been written. |
| if (outputFormat.equals(Format.HTML)) { |
| writer.write("</div></body></html>\n"); |
| } |
| writer.close(); |
| } catch (InterruptedException ignored) { |
| } catch (IOException e) { |
| System.err.println("Unable to write to dart.speedtracerlog '" |
| + (fileName == null ? "" : fileName) + "'"); |
| e.printStackTrace(); |
| } catch (JSONException e) { |
| // TODO(jat): Auto-generated catch block |
| e.printStackTrace(); |
| } finally { |
| shutDownLatch.countDown(); |
| } |
| } |
| } |
| |
| /** |
| * Records a LOG_MESSAGE type of SpeedTracer event. |
| */ |
| private class MarkTimelineEvent extends TraceEvent { |
| public MarkTimelineEvent(TraceEvent parent) { |
| super(); |
| if (parent != null) { |
| parent.children.add(this); |
| } |
| } |
| |
| @Override |
| JSONObject toJson() throws JSONException { |
| JSONObject json = new JSONObject(); |
| json.put("type", 11); |
| double startMs = convertToMilliseconds(getStartTimeNanos()); |
| json.put("time", startMs); |
| json.put("duration", 0.0); |
| JSONObject jsonData = new JSONObject(); |
| for (int i = 0; i < data.size(); i += 2) { |
| jsonData.put(data.get(i), data.get(i + 1)); |
| } |
| json.put("data", jsonData); |
| return json; |
| } |
| } |
| |
| /** |
| * Annotate the current event on the top of the stack with more information. |
| * The method expects key, value pairs, so there must be an even number of |
| * parameters. |
| * |
| * @param data JSON property, value pair to add to current event. |
| */ |
| public static void addData(String... data) { |
| Tracer.get().addDataImpl(data); |
| } |
| |
| /** |
| * Create a new global instance. Force the zero time to be recorded and the |
| * log to be opened if the default logging is turned on with the <code> |
| * -Ddart.speedtracerlog</code> VM property. |
| * |
| * This method is only intended to be called once. |
| */ |
| public static void init() { |
| get(); |
| } |
| |
| /** |
| * Returns true if the trace output file is configured. This is intended to be |
| * the quickest possible check, statically determined. |
| */ |
| public static boolean canTrace() { |
| return logFile != null; |
| } |
| |
| /** |
| * Adds a LOG_MESSAGE SpeedTracer event to the log. This represents a single |
| * point in time and has a special representation in the SpeedTracer UI. |
| */ |
| public static void markTimeline(String message) { |
| Tracer.get().markTimelineImpl(message); |
| } |
| |
| /** |
| * Signals that a new event has started. You must end each event for each |
| * corresponding call to {@code start}. You may nest timing calls. |
| * |
| * @param type the type of event |
| * @param data a set of key-value pairs (each key is followed by its value) |
| * that contain additional information about the event |
| * @return an Event object to be ended by the caller |
| */ |
| public static TraceEvent start(EventType type, String... data) { |
| return Tracer.get().startImpl(type, data); |
| } |
| |
| private static double convertToMilliseconds(long nanos) { |
| return nanos / 1000000.0d; |
| } |
| |
| /** |
| * Convenience method for ending event, which might possibly be null. |
| */ |
| public static void end(TraceEvent event, String... data) { |
| if (event != null) { |
| event.end(data); |
| } |
| } |
| |
| /** |
| * For accessing the logger as a singleton, you can retrieve the global |
| * instance. It is prudent, but not necessary to first initialize the |
| * singleton with a call to {@link #init()} to set the base time. |
| * |
| * @return the current global {@link Tracer} instance. |
| */ |
| private static Tracer get() { |
| return LazySpeedTracerLoggerHolder.singleton; |
| } |
| |
| private static boolean getBooleanProperty(String propName) { |
| try { |
| return System.getProperty(propName) != null; |
| } catch (RuntimeException ruEx) { |
| return false; |
| } |
| } |
| |
| private final boolean enabled; |
| |
| private final DummyEvent dummyEvent = new DummyEvent(); |
| |
| private BlockingQueue<TraceEvent> eventsToWrite; |
| |
| private final boolean fileLoggingEnabled; |
| |
| private CountDownLatch flushLatch; |
| |
| private TraceEvent flushSentinel; |
| |
| private Format outputFormat; |
| |
| private ThreadLocal<Stack<TraceEvent>> pendingEvents; |
| |
| private CountDownLatch shutDownLatch; |
| |
| private TraceEvent shutDownSentinel; |
| |
| private List<GarbageCollectorMXBean> gcMXBeans; |
| |
| private Map<String, Long> lastGcTimes; |
| |
| private final ElapsedNormalizedTimeKeeper elapsedTimeKeeper; |
| |
| private final ProcessNormalizedTimeKeeper processCpuTimeKeeper; |
| |
| private final ThreadNormalizedTimeKeeper threadCpuTimeKeeper; |
| |
| /** |
| * Constructor intended for unit testing. |
| * |
| * @param writer alternative {@link Writer} to send speed tracer output. |
| */ |
| Tracer(Writer writer, Format format) { |
| enabled = true; |
| fileLoggingEnabled = true; |
| outputFormat = format; |
| eventsToWrite = openLogWriter(writer, ""); |
| pendingEvents = initPendingEvents(); |
| elapsedTimeKeeper = new ElapsedNormalizedTimeKeeper(); |
| processCpuTimeKeeper = new ProcessNormalizedTimeKeeper(); |
| threadCpuTimeKeeper = new ThreadNormalizedTimeKeeper(); |
| shutDownSentinel = new DummyEvent(); |
| flushSentinel = new DummyEvent(); |
| shutDownLatch = new CountDownLatch(1); |
| } |
| |
| private Tracer() { |
| fileLoggingEnabled = logFile != null; |
| enabled = fileLoggingEnabled; |
| |
| if (enabled) { |
| elapsedTimeKeeper = new ElapsedNormalizedTimeKeeper(); |
| processCpuTimeKeeper = new ProcessNormalizedTimeKeeper(); |
| threadCpuTimeKeeper = new ThreadNormalizedTimeKeeper(); |
| |
| if (fileLoggingEnabled) { |
| // Allow a system property to override the default output format |
| Format format = Format.HTML; |
| if (defaultFormatString != null) { |
| for (Format value : Format.values()) { |
| if (value.name().toLowerCase().equals(defaultFormatString.toLowerCase())) { |
| format = value; |
| break; |
| } |
| } |
| } |
| outputFormat = format; |
| eventsToWrite = openDefaultLogWriter(); |
| |
| shutDownSentinel = new TraceEvent(); |
| flushSentinel = new TraceEvent(); |
| shutDownLatch = new CountDownLatch(1); |
| } |
| |
| if (logGcTime) { |
| gcMXBeans = ManagementFactory.getGarbageCollectorMXBeans(); |
| lastGcTimes = new ConcurrentHashMap<String, Long>(); |
| } |
| |
| pendingEvents = initPendingEvents(); |
| } else { |
| elapsedTimeKeeper = null; |
| processCpuTimeKeeper = null; |
| threadCpuTimeKeeper = null; |
| } |
| } |
| |
| public void addDataImpl(String... data) { |
| Stack<TraceEvent> threadPendingEvents = pendingEvents.get(); |
| if (threadPendingEvents.isEmpty()) { |
| throw new IllegalStateException("Tried to add data to an event that never started!"); |
| } |
| |
| TraceEvent currentEvent = threadPendingEvents.peek(); |
| currentEvent.addData(data); |
| } |
| |
| public void markTimelineImpl(String message) { |
| Stack<TraceEvent> threadPendingEvents = pendingEvents.get(); |
| TraceEvent parent = null; |
| if (!threadPendingEvents.isEmpty()) { |
| parent = threadPendingEvents.peek(); |
| } |
| TraceEvent newEvent = new MarkTimelineEvent(parent); |
| threadPendingEvents.push(newEvent); |
| newEvent.end("message", message); |
| } |
| |
| void addGcEvents(TraceEvent refEvent) { |
| // we're not sending GC events to the dartboard, so we only record them |
| // to file |
| if (!fileLoggingEnabled) { |
| return; |
| } |
| |
| for (GarbageCollectorMXBean gcMXBean : gcMXBeans) { |
| String gcName = gcMXBean.getName(); |
| Long lastGcTime = lastGcTimes.get(gcName); |
| long currGcTime = gcMXBean.getCollectionTime(); |
| if (lastGcTime == null) { |
| lastGcTime = 0L; |
| } |
| if (currGcTime > lastGcTime) { |
| // create a new event |
| long gcDurationNanos = (currGcTime - lastGcTime) * 1000000L; |
| TraceEvent gcEvent = |
| new GcEvent(refEvent, gcName, gcMXBean.getCollectionCount(), gcDurationNanos); |
| |
| eventsToWrite.add(gcEvent); |
| lastGcTimes.put(gcName, currGcTime); |
| } |
| } |
| } |
| |
| void addOverheadEvent(TraceEvent refEvent) { |
| TraceEvent overheadEvent = new TraceEvent(refEvent, SpeedTracerEventType.OVERHEAD); |
| // measure the time between the end of refEvent and now |
| overheadEvent.setStartsAfter(refEvent); |
| overheadEvent.updateDuration(); |
| |
| refEvent.extendDuration(overheadEvent); |
| } |
| |
| void endImpl(TraceEvent event, String... data) { |
| if (!enabled) { |
| return; |
| } |
| |
| if (data.length % 2 == 1) { |
| throw new IllegalArgumentException("Unmatched data argument"); |
| } |
| |
| Stack<TraceEvent> threadPendingEvents = pendingEvents.get(); |
| if (threadPendingEvents.isEmpty()) { |
| throw new IllegalStateException("Tried to end an event that never started!"); |
| } |
| TraceEvent currentEvent = threadPendingEvents.pop(); |
| currentEvent.updateDuration(); |
| |
| while (currentEvent != event && !threadPendingEvents.isEmpty()) { |
| // Missed a closing end for one or more frames! Try to sync back up. |
| currentEvent.addData("Missed", |
| "This event was closed without an explicit call to Event.end()"); |
| currentEvent = threadPendingEvents.pop(); |
| currentEvent.updateDuration(); |
| } |
| |
| if (threadPendingEvents.isEmpty() && currentEvent != event) { |
| currentEvent.addData("Missed", "Fell off the end of the threadPending events"); |
| } |
| |
| if (logGcTime) { |
| addGcEvents(currentEvent); |
| } |
| |
| currentEvent.addData(data); |
| |
| if (logOverheadTime) { |
| addOverheadEvent(currentEvent); |
| } |
| |
| if (threadPendingEvents.isEmpty()) { |
| if (fileLoggingEnabled) { |
| eventsToWrite.add(currentEvent); |
| } |
| } |
| } |
| |
| /** |
| * Notifies the background thread to finish processing all data in the queue. |
| * Blocks the current thread until the data is flushed in the Log Writer |
| * thread. |
| */ |
| void flush() { |
| if (!fileLoggingEnabled) { |
| return; |
| } |
| |
| try { |
| // Wait for the other thread to drain the queue. |
| flushLatch = new CountDownLatch(1); |
| eventsToWrite.add(flushSentinel); |
| flushLatch.await(); |
| } catch (InterruptedException e) { |
| // Ignored |
| } |
| } |
| |
| TraceEvent startImpl(EventType type, String... data) { |
| if (!enabled) { |
| return dummyEvent; |
| } |
| |
| if (data.length % 2 == 1) { |
| throw new IllegalArgumentException("Unmatched data argument"); |
| } |
| |
| Stack<TraceEvent> threadPendingEvents = pendingEvents.get(); |
| TraceEvent parent = null; |
| if (!threadPendingEvents.isEmpty()) { |
| parent = threadPendingEvents.peek(); |
| } else { |
| // reset the thread CPU time base for top-level events (so events can be |
| // properly sequenced chronologically) |
| threadCpuTimeKeeper.resetTimeBase(); |
| } |
| |
| TraceEvent newEvent = new TraceEvent(parent, type, data); |
| // Add a field to the top level event in order to track the base time |
| // so we can re-normalize the data |
| if (threadPendingEvents.size() == 0) { |
| long baseTime = |
| logProcessCpuTime ? processCpuTimeKeeper.zeroTimeMillis() : (logThreadCpuTime |
| ? threadCpuTimeKeeper.zeroTimeMillis() : elapsedTimeKeeper.zeroTimeMillis()); |
| newEvent.addData("baseTime", "" + baseTime); |
| } |
| threadPendingEvents.push(newEvent); |
| return newEvent; |
| } |
| |
| private ThreadLocal<Stack<TraceEvent>> initPendingEvents() { |
| return new ThreadLocal<Stack<TraceEvent>>() { |
| @Override |
| protected Stack<TraceEvent> initialValue() { |
| return new Stack<TraceEvent>(); |
| } |
| }; |
| } |
| |
| private BlockingQueue<TraceEvent> openDefaultLogWriter() { |
| Writer writer = null; |
| if (enabled) { |
| try { |
| writer = new BufferedWriter(new FileWriter(logFile)); |
| return openLogWriter(writer, logFile); |
| } catch (IOException e) { |
| System.err.println("Unable to open dart.speedtracerlog '" + logFile + "'"); |
| e.printStackTrace(); |
| } |
| } |
| return null; |
| } |
| |
| private BlockingQueue<TraceEvent> openLogWriter(final Writer writer, final String fileName) { |
| try { |
| if (outputFormat.equals(Format.HTML)) { |
| writer.write("<HTML isdump=\"true\"><body>" |
| + "<style>body {font-family:Helvetica; margin-left:15px;}</style>" |
| + "<h2>Performance dump from GWT</h2>" |
| + "<div>This file contains data that can be viewed with the " |
| + "<a href=\"http://code.google.com/speedtracer\">SpeedTracer</a> " |
| + "extension under the <a href=\"http://chrome.google.com/\">" |
| + "Chrome</a> browser.</div><p><span id=\"info\">" |
| + "(You must install the SpeedTracer extension to open this file)</span></p>" |
| + "<div style=\"display: none\" id=\"traceData\" version=\"0.17\">\n"); |
| } |
| } catch (IOException e) { |
| System.err.println("Unable to write to dart.speedtracerlog '" |
| + (fileName == null ? "" : fileName) + "'"); |
| e.printStackTrace(); |
| return null; |
| } |
| |
| final BlockingQueue<TraceEvent> eventQueue = new LinkedBlockingQueue<TraceEvent>(); |
| |
| Runtime.getRuntime().addShutdownHook(new Thread() { |
| @Override |
| public void run() { |
| try { |
| // Wait for the other thread to drain the queue. |
| eventQueue.add(shutDownSentinel); |
| shutDownLatch.await(); |
| } catch (InterruptedException e) { |
| // Ignored |
| } |
| } |
| }); |
| |
| // Background thread to write SpeedTracer events to log |
| Thread logWriterWorker = new LogWriterThread(writer, fileName, eventQueue); |
| |
| // Lower than normal priority. |
| logWriterWorker.setPriority((Thread.MIN_PRIORITY + Thread.NORM_PRIORITY) / 2); |
| |
| /* |
| * This thread must be daemon, otherwise shutdown hooks would never begin to |
| * run, and an app wouldn't finish. |
| */ |
| logWriterWorker.setDaemon(true); |
| logWriterWorker.setName("SpeedTracerLogger writer"); |
| logWriterWorker.start(); |
| return eventQueue; |
| } |
| } |