@GwtIncompatible(value="java.util.concurrent")
final class Tracer
extends java.lang.Object
Example usage:
Tracer.initCurrentThreadTrace(); // must be called in each Thread Tracer wholeRequest = new Tracer(null, "Request " + params); try { ... t = new Tracer("Database", "getName()"); try { name = database.getName(); } finally { t.stop(); } ... t = new Tracer(null, "call sendmail"); try { sendMessage(); } finally { t.stop(); } ... t = new Tracer("Database", "updateinfo()"); try { database.updateinfo("new info"); } finally { t.stop(); } ... } finally { if (wholeRequest.stop() > 1000) { // more than a second, better log Tracer.logAndClearCurrentThreadTrace(); } else { Tracer.clearCurrentThreadTrace(); } }Now slow requests will produce a report like this:
10.452 Start Request cmd=dostuff 3 10.455 Start [Database] getName() 34 10.489 Done 34 ms [Database] getName() 3 10.491 Start call sendmail 1042 11.533 Done 1042 ms call sendmail 0 11.533 Start [Database] updateinfo() 3 11.536 Done 3 ms [Database] updateinfo() 64 11.600 Done 1148 ms Request cmd=dostuff TOTAL Database 2 (37 ms)If you enabled pretty-printing by calling
setPrettyPrint(boolean)
,
it will print more easily readable reports that use indentation to visualize
the tracer hierarchy and dynamically adjusts the padding to handle large
durations. Like:
10.452 Start Request cmd=dostuff 3 10.455 Start | [Database] getName() 34 10.489 Done 34 ms | [Database] getName() 3 10.491 Start | call sendmail 1042 11.533 Done 1042 ms | call sendmail 0 11.533 Start | [Database] updateinfo() 3 11.536 Done 3 ms | [Database] updateinfo() 64 11.600 Done 1148 ms Request cmd=dostuff TOTAL Database 2 (37 ms)Pretty-printing is an application global setting and should only be called in the main setup of an application, not in library code. Now you can easily see that sendmail is causing your problems, not the two database calls. You can easily add additional tracing statistics to your Trace output by adding additional tracing statistics. Simply add to your initialization code:
Tracer.addTracingStatistic(myTracingStatistic)where myTracingStatistic implements the
Tracer.TracingStatistic
interface.
The class com.google.monitoring.tracing.TracingStatistics contains
several useful statistics such as CPU time, wait time, and memory usage.
If you add your own tracing statistics, the output is not quite as pretty,
but includes additional useful information.
If a Trace is given a type (the first argument to the constructor) and multiple Traces are done on that type then a "TOTAL line will be produced showing the total number of traces and the sum of the time ("TOTAL Database 2 (37 ms)" in our example). These traces should be mutually exclusive or else the sum won't make sense (the time will be double counted if the second starts before the first ends).
It is also possible to have a "silent" Tracer which does not appear in the trace because it was faster than the silence threshold. This threshold can be set for the for the current ThreadTrace with setDefaultSilenceThreshold(threshold), or on a per-Tracer basis with t.stop(threshold). Silent tracers are still counted in the type totals, so these events are not completely lost.
WARNING: This code makes a big assumption that everything for a given trace is done within a single thread. It uses threads to identify requests. It is fine to have multiple requests traced in multiple simultaneous threads but it is not ok to have any given request traced in multiple threads. (the results will be scattered across reports). Java objects do not support destructors (as in C++) so Tracer is not robust when exceptions are thrown. Each Tracer object should be wrapped in a try/finally block so that if an exception is thrown, the Tracer.stop() method is guaranteed to be called.
A thread must call initCurrentThreadTrace()
to enable the
Tracer logging, otherwise Tracer does nothing. The requirement to call
initCurrentThreadTrace
avoids the situation where Tracer is called
without the explicit knowledge of the application authors because they
happen to use a class in another package that uses Tracer. If logCurrentThreadTrace()
is called without calling initCurrentThreadTrace()
, then a Third Eye WARNING message is logged,
which should help track down the problem.
Modifier and Type | Class and Description |
---|---|
(package private) static class |
Tracer.AtomicTracerStatMap
This class encapsulates a map for keeping track of tracing statistics.
|
private static class |
Tracer.Event
An event is created every time a Tracer is created or stopped
|
(package private) static interface |
Tracer.InternalClock
For unit testing.
|
(package private) static class |
Tracer.Stat
Statistics for a given tracer type
|
(package private) static class |
Tracer.ThreadTrace
Stores a thread's Trace
|
(package private) static interface |
Tracer.TracingStatistic
A TracingStatistic allows the program to add additional optional
statistics to the trace output.
|
Modifier and Type | Field and Description |
---|---|
(package private) static Tracer.InternalClock |
clock
Default clock that calls through to the system clock.
|
private java.lang.String |
comment
A comment string for the report
|
private static boolean |
defaultPrettyPrint
Whether pretty printing is enabled.
|
private static java.util.List<Tracer.TracingStatistic> |
extraTracingStatistics |
private long[] |
extraTracingValues
Values returned by extraTracingStatistics
|
(package private) static java.util.logging.Logger |
logger |
(package private) static int |
MAX_TRACE_SIZE
We limit the number of events in a Trace in order to catch memory
leaks (a thread that keeps logging events and never clears them).
|
(package private) java.lang.Thread |
startThread
Record our starter thread in order to trap Traces that are started in one
thread and stopped in another
|
private long |
startTimeMs
Start time of the trace
|
private long |
stopTimeMs
Stop time of the trace, non-final
|
private static java.lang.ThreadLocal<Tracer.ThreadTrace> |
traces
Holds the ThreadTrace for each thread.
|
private java.lang.String |
type
The type for grouping traces, may be null
|
private static Tracer.AtomicTracerStatMap |
typeToCountMap
This map tracks counts of tracers for each type over all time.
|
private static Tracer.AtomicTracerStatMap |
typeToSilentMap
This map tracks counts of silent tracers for each type over all time.
|
private static Tracer.AtomicTracerStatMap |
typeToTimeMap
This map tracks time (ms) for each type over all time.
|
private static Tracer.Stat |
ZERO_STAT |
Constructor and Description |
---|
Tracer(java.lang.String comment)
Create a tracer that isn't summed as part of a total
|
Tracer(java.lang.String type,
java.lang.String comment)
Create and start a tracer.
|
Modifier and Type | Method and Description |
---|---|
(package private) static int |
addTracingStatistic(Tracer.TracingStatistic tracingStatistic)
Adds a new tracing statistic to a trace
|
(package private) static void |
appendSpaces(java.lang.StringBuilder sb,
int numSpaces)
Gets a string of spaces of the length specified.
|
(package private) static void |
clearCurrentThreadTrace()
Throw away any Trace associated with the current thread.
|
(package private) static void |
clearThreadTrace()
Remove any ThreadTrace associated with the current thread
|
(package private) static void |
clearTracingStatisticsTestingOnly()
For testing purposes only.
|
(package private) static void |
enableTypeMaps()
This method MUST be called before getTypeToCountMap (and friends)
will return a valid map.
|
private static java.lang.String |
formatTime(long time)
Return the sec.ms part of time (if time = "20:06:11.566", "11.566")
|
(package private) static java.lang.String |
getCurrentThreadTraceReport()
Returns a timer report similar to the one described in the class comment.
|
(package private) static Tracer.Stat |
getStatsForType(java.lang.String type)
Gets the Stat for a tracer type; never returns null
|
(package private) static Tracer.ThreadTrace |
getThreadTrace()
Get the ThreadTrace for the current thread, creating one if necessary.
|
(package private) static java.util.Map<java.lang.String,java.lang.Long> |
getTypeToCountMap()
Used for exporting this data via varz.
|
(package private) static java.util.Map<java.lang.String,java.lang.Long> |
getTypeToSilentMap()
Used for exporting this data via varz.
|
(package private) static java.util.Map<java.lang.String,java.lang.Long> |
getTypeToTimeMap()
Used for exporting this data via varz.
|
(package private) static void |
initCurrentThreadTrace()
Initialize the trace associated with the current thread by clearing
out any existing trace.
|
(package private) static void |
initCurrentThreadTrace(int defaultSilenceThreshold) |
(package private) static void |
logAndClearCurrentThreadTrace()
logCurrentThreadTrace() then clearCurrentThreadTrace()
|
(package private) static void |
logCurrentThreadTrace()
Logs a timer report similar to the one described in the class comment.
|
private static java.lang.String |
longToPaddedString(long v,
int digitsColumnWidth)
Converts 'v' to a string and pads it with up to 16 spaces for
improved alignment.
|
private static int |
numDigits(long n)
Gets the number of digits in an integer when printed in base 10.
|
(package private) static void |
setDefaultSilenceThreshold(int threshold) |
(package private) static void |
setPrettyPrint(boolean enabled)
Sets whether pretty printing is enabled.
|
(package private) long |
stop()
Stop the trace using the default silenceThreshold
|
(package private) long |
stop(int silenceThreshold)
Stop the trace.
|
java.lang.String |
toString() |
static final java.util.logging.Logger logger
private static volatile boolean defaultPrettyPrint
private static java.util.List<Tracer.TracingStatistic> extraTracingStatistics
private long[] extraTracingValues
@Nullable private final java.lang.String type
private final java.lang.String comment
private final long startTimeMs
private long stopTimeMs
final java.lang.Thread startThread
static final int MAX_TRACE_SIZE
static Tracer.InternalClock clock
@Nullable private static Tracer.AtomicTracerStatMap typeToCountMap
@Nullable private static Tracer.AtomicTracerStatMap typeToSilentMap
@Nullable private static Tracer.AtomicTracerStatMap typeToTimeMap
private static final Tracer.Stat ZERO_STAT
private static java.lang.ThreadLocal<Tracer.ThreadTrace> traces
Tracer(@Nullable java.lang.String type, @Nullable java.lang.String comment)
type
- The type for totalingcomment
- Comment about this tracerTracer(java.lang.String comment)
comment
- Comment about this tracerprivate static java.lang.String longToPaddedString(long v, int digitsColumnWidth)
v
- The value to convert.digitsColumnWidth
- The desired with of the string.private static int numDigits(long n)
n
- The value.static void appendSpaces(java.lang.StringBuilder sb, int numSpaces)
sb
- The string builder to append to.numSpaces
- The number of spaces in the string.static int addTracingStatistic(Tracer.TracingStatistic tracingStatistic)
tracingStatistic
- to enable a runstatic void clearTracingStatisticsTestingOnly()
long stop(int silenceThreshold)
silenceThreshold
- Traces for time less than silence_threshold
ms will be left out of the trace report. A value of -1 indicates
that the current ThreadTrace silence_threshold should be used.long stop()
public java.lang.String toString()
toString
in class java.lang.Object
static void setDefaultSilenceThreshold(int threshold)
static void initCurrentThreadTrace()
static void initCurrentThreadTrace(int defaultSilenceThreshold)
static java.lang.String getCurrentThreadTraceReport()
static void logCurrentThreadTrace()
static void clearCurrentThreadTrace()
static void logAndClearCurrentThreadTrace()
static void setPrettyPrint(boolean enabled)
enabled
- Whether to enable pretty printing.static void enableTypeMaps()
@Nullable static java.util.Map<java.lang.String,java.lang.Long> getTypeToCountMap()
@Nullable static java.util.Map<java.lang.String,java.lang.Long> getTypeToSilentMap()
@Nullable static java.util.Map<java.lang.String,java.lang.Long> getTypeToTimeMap()
static Tracer.Stat getStatsForType(java.lang.String type)
private static java.lang.String formatTime(long time)
static Tracer.ThreadTrace getThreadTrace()
static void clearThreadTrace()