com.google.gwt.dev.util.log.speedtracer.SpeedTracerLogger Maven / Gradle / Ivy
/*
* Copyright 2010 Google Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License"); you may not
* use this file except in compliance with the License. You may obtain a copy of
* the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
* WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
* License for the specific language governing permissions and limitations under
* the License.
*/
package com.google.gwt.dev.util.log.speedtracer;
import com.google.gwt.dev.json.JsonArray;
import com.google.gwt.dev.json.JsonObject;
import com.google.gwt.dev.shell.DevModeSession;
import com.google.gwt.dev.util.collect.Lists;
import com.google.gwt.dev.util.log.dashboard.DashboardNotifierFactory;
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.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;
import java.util.logging.Level;
import java.util.logging.Logger;
/**
* 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.
*
*
* Enable logging by setting the system property {@code gwt.speedtracerlog} to
* the output file path.
*
*
*/
public final class SpeedTracerLogger {
private static final Logger log = Logger.getLogger(SpeedTracerLogger.class.getName());
// Log file name (logging is enabled if this is non-null)
private static final String logFile =
System.getProperty("gwt.speedtracerlog");
// Allow a system property to override the default output format
private static final String defaultFormatString =
System.getProperty("gwt.speedtracerformat");
// Use cumulative multi-threaded process cpu time instead of wall time
private static final boolean logProcessCpuTime =
getBooleanProperty("gwt.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("gwt.speedtracer.logThreadCpuTime");
// Turn on logging summarizing gc time during an event
private static final boolean logGcTime =
getBooleanProperty("gwt.speedtracer.logGcTime");
// Turn on logging estimating overhead used for speedtracer logging.
private static final boolean logOverheadTime =
getBooleanProperty("gwt.speedtracer.logOverheadTime");
// Disable logging of JSNI calls and callbacks to reduce memory usage where
// the heap is already tight.
private static final boolean jsniCallLoggingEnabled =
!getBooleanProperty("gwt.speedtracer.disableJsniLogging");
static {
// verify configuration
if (logProcessCpuTime && logThreadCpuTime) {
throw new RuntimeException("System properties are misconfigured: "
+ "Specify one or the other of 'gwt.speedtracer.logProcessCpuTime' "
+ "or 'gwt.speedtracer.logThreadCpuTime', not both.");
}
}
/**
* Represents a node in a tree of SpeedTracer events.
*/
public class Event {
protected final EventType type;
List children;
List data;
DevModeSession devModeSession;
long elapsedDurationNanos;
long elapsedStartTimeNanos;
long processCpuDurationNanos;
long processCpuStartTimeNanos;
long threadCpuDurationNanos;
long threadCpuStartTimeNanos;
Event() {
if (enabled) {
if (logThreadCpuTime) {
threadCpuTimeKeeper.resetTimeBase();
}
recordStartTime();
this.data = Lists.create();
this.children = Lists.create();
} else {
this.processCpuStartTimeNanos = 0L;
this.threadCpuStartTimeNanos = 0L;
this.elapsedStartTimeNanos = 0L;
this.data = null;
this.children = null;
}
this.type = null;
}
Event(DevModeSession session, Event parent, EventType type, String... data) {
if (parent != null) {
parent.children = Lists.add(parent.children, this);
}
this.type = type;
assert (data.length % 2 == 0);
recordStartTime();
this.data = Lists.create(data);
this.children = Lists.create();
this.devModeSession = session;
}
/**
* @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 = Lists.addAll(this.data, data);
}
}
/**
* Signals the end of the current event.
*/
public void end(String... data) {
endImpl(this, data);
}
public DevModeSession getDevModeSession() {
return devModeSession;
}
/**
* 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(Event 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(Event refEvent) {
elapsedStartTimeNanos = refEvent.elapsedStartTimeNanos + refEvent.elapsedDurationNanos;
processCpuStartTimeNanos =
refEvent.processCpuStartTimeNanos + refEvent.processCpuDurationNanos;
threadCpuStartTimeNanos = refEvent.threadCpuStartTimeNanos + refEvent.threadCpuDurationNanos;
}
JsonObject toJson() {
JsonObject json = JsonObject.create();
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 = JsonObject.create();
for (int i = 0; i < data.size(); i += 2) {
jsonData.put(data.get(i), data.get(i + 1));
}
json.put("data", jsonData);
JsonArray jsonChildren = JsonArray.create();
for (Event child : children) {
jsonChildren.add(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:
*
* - Elapsed (wall-clock) time
* - Process CPU time
* - Thread CPU time
*
*/
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 Event {
@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 Event {
private Event 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(Event refEvent, String gcType, long collectionCount, long durationNanos) {
super(null, 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 zeroTimeNanos;
public ElapsedNormalizedTimeKeeper() {
zeroTimeNanos = System.nanoTime();
}
public long normalizedTimeNanos() {
return System.nanoTime() - zeroTimeNanos;
}
}
/**
* 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;
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);
} catch (Exception ex) {
throw new RuntimeException(ex);
}
}
public long normalizedTimeNanos() {
try {
return (Long) getProcessCpuTimeMethod.invoke(osMXBean) - zeroTimeNanos;
} catch (Exception ex) {
throw new RuntimeException(ex);
}
}
}
/**
* 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 resettableTimeBase = new ThreadLocal();
private final long zeroTimeNanos;
public ThreadNormalizedTimeKeeper() {
threadMXBean = ManagementFactory.getThreadMXBean();
if (!threadMXBean.isCurrentThreadCpuTimeSupported()) {
throw new RuntimeException("Current thread cpu time not supported");
}
zeroTimeNanos = System.nanoTime();
}
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());
}
}
/**
* Initializes the singleton on demand.
*/
private static class LazySpeedTracerLoggerHolder {
public static SpeedTracerLogger singleton = new SpeedTracerLogger();
}
/**
* 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 threadEventQueue;
private final Writer writer;
public LogWriterThread(
Writer writer, String fileName, final BlockingQueue 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) {
Event 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("