com.google.dart.compiler.metrics.Tracer.java Source code

Java tutorial

Introduction

Here is the source code for com.google.dart.compiler.metrics.Tracer.java

Source

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