Home

Trace Event Logger

This logger is based on JUL to allow fast JSON traces to be written to disk. It is not lockless or nanosecond precise, but is fast and simple to use and configure.

A snapshot taker is provided in order to write slow transactions onto disk.

An asynchronous writer is available for putting the IO bottleneck on another thread. It is typically much faster than the FileHandler from JUL.

This is a logger helper designed to facilitate entry-exit analysis. The events generated by this logger are saved in a JSON-like message format, providing extra information associated with each event. The typical event types include:

• Durations:

  • B: Begin
  • E: End
  • X: Complete (event with a duration field)
  • i: Instant / Info

• Asynchronous Nested Messages:

  • b: Nested Begin
  • n: Nested Info
  • e: Nested End

• Flows:

  • s: Flow Begin
  • t: Flow Step (Info)
  • f: Flow End

• Object Tracking:

  • N: Object Created
  • D: Object Destroyed

• Mark Events:

  • R: Marker Event

• Counter Events:

  • C: Counter Event

Usage

To use durations and/or flows, refer to ScopeLog and FlowScopeLog. Durations are typically used to instrument simple methods, while flows are preferred when there are links to be made with other threads.

To use Asynchronous Nested Messages, check traceAsyncStart and traceAsyncEnd].

To use Object Tracking, see traceObjectCreation and traceObjectDestruction.

To use free form tracing, check traceInstant.

Examples

see Examples

Viewing results

While one could open the traces in their favorite text editor, results are better with a GUI. One could open the resulting json files in either chrome://tracing or Eclipse Trace Compass. You will need to install trace event parser support by clicking on the Tools->Add-ons... menu and selecting Trace Compass TraceEvent Parser in trace compass to load the JSON files. If the trace is malformed due to a handler not being configured properly, the program jsonify.py supplied in the root of the project can help restore it.

// python 3 jsonify.py -input -output
python3 jsonify.py LOG_FILE log.json

Another option would be to add the -DenableMonitoring=true flag to enable the JMX beans counters. These can be read using VisualVM or jconsole.

Video tutorial

Performance

On an Intel i5-1145G7 @ 2.60GHz with an NVME hard drive, using an AsyncFileHandler instead of the classic FileHandler leads to events being logged from 45 us/event (FileHandler) to 1.1 us/event (AsyncFileHandler). In other words, AsyncFileHandler can write 900k events in the time it takes FileHandler to write 22k events One could also take advantage of the cache effect. If the data is not saturating the IO, speed is even higher.

Action	Overhead
Instrumentation	72 ns
AsyncFileHandler	1100 ns
FileHandler	45000 ns
Beans-Enabled AsyncFileHandler	1400 ns

Design Philosophy

The design philosophy of this class is heavily inspired by the trace event format of Google. The full specification is available here.

The main goals of this logger helper are clarity of output and simplicity for the developer. While performance is a nice-to-have, it is not the main concern of this helper. A minor performance impact compared to simply logging the events is to be expected.

Running

The jar needs to be loaded for it to run. Assuming the jar is called trace-event-logger-x.y.z.jar, one would need to first build their java application with the jar in the classpath such as

user@host:~$ javac -cp trace-event-logger-x.y.z.jar my-project

-cp: loads the jar

and then, run it as

user@host:~$ java -Djava.util.logging.config.file=path/to/logging.properties -p bin:path/to/trace-event-logger-x.y.z.jar -m package/path/to.Main

-Djava.util.logging.config.file: the path of the logging.properties

-p: the packages, the location of the classes and the external logging jar

-m: the location of the main module to run.

Handlers

There are two new handlers introduced.

• The AsyncFileHandler: org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler in the logging properties. It handles serialization and writing to disk in a separate thread from the caller. Note: this will require explicitly killing a process when it exits as it is a separate thread.

• The SnapshotHandler: org.eclipse.tracecompass.traceeventlogger.SnapshotHandler in the logging properties. It writes all events to a fixed length queue (culling at the front when full) and dumps the entire queue to disk when a defined latency is hit, for example when a span lasts over 30 seconds.