SELogger: (Near-)Omniscient Logging Tool for Java

SELogger is a Java Agent to record an execcution trace of a Java program. The tool name "SE" means Software Engineering, because the tool is developed for software engineering research topics including omniscient debugging.

The design of this tool is partly explained in the following articles.

• Kazumasa Shimari, Takashi Ishio, Tetsuya Kanda, Naoto Ishida, Katsuro Inoue: "NOD4J: Near-omniscient debugging tool for Java using size-limited execution trace", Science of Computer Programming, Volume 206, 2021, 102630, ISSN 0167-6423, https://doi.org/10.1016/j.scico.2021.102630.
• Kazumasa Shimari, Takashi Ishio, Tetsuya Kanda, Katsuro Inoue: "Near-Omniscient Debugging for Java Using Size-Limited Execution Trace", ICSME 2019 Tool Demo Track, https://ieeexplore.ieee.org/abstract/document/8919216

Usage

Execute your Java program with SELogger using -javaagent option as follows.

    java -javaagent:/path/to/selogger-0.6.0.jar [Application Options]

SELogger produces a file named trace.json including the execution trace. The file format is described in the DataFormat.md file. The DataFormat file also includes the list of recordable runtime events.

To demonstrate the behavior, a simple program is included in this repository.

     5:	public static void main(String[] args) {
     6:		int s = 0;
     7:		for (int i=0; i<10; i++) {
     8:			s = Integer.sum(s, i);
     9:		}
    10:		System.out.println(s);
    11:	}

An execution of the program with SELogger produces an execution trace file. In the trace file, you can find actual behavior of the program. For example, line 8 updates a local variable s 10 times. The event occurrences are recorded as a single JSON object as follows.

{"cname":"selogger/testdata/Demo","mname":"main",...,
 "line":8,...,
 "event":"LOCAL_STORE",
 "attr"{"type":"int","name":"s",...},
 "freq":10,...,
 "value":[0,1,3,6,10,15,21,28,36,45],...},

The cname, mname, and line fields indicate the class name, method name, and line number to identify a source code location. The attr field indicates that the event is recorded when an int value is stored to the variable s. The freq field shows that the event occurred 10 times. The value field shows actual values assigned to the variable.

SELogger also records various events such as method call parameters, return values, and field access. A list of runtime events is available in the DataFormat.md file.

Configure options

SELogger accepts some options. Each option is specified by option=value style with commas (","). For example:

    java -javaagent:/path/to/selogger-0.6.0.jar=format=freq,weaverlog=log.txt [Application Options]

If you would like to record the behavior of test cases executed by Maven Surefire, you can use an argLine option.

    mvn -DargLine="-javaagent:/path/to/selogger-0.6.0.jar=format=freq,weaverlog=log.txt" test

Instead of a command line option, you can write the same option in your pom.xml file as follows.

    <plugin>
      <groupId>org.apache.maven.plugins</groupId>
      <artifactId>maven-surefire-plugin</artifactId>
      <configuration>
       <argLine>-javaagent:/path/to/selogger-0.6.0.jar=format=freq,weaverlog=log.txt</argLine>
       </configuration>
       <executions>...</executions>
     </plugin>

Change a trace file name

You can change a trace file name from the default trace.json using the trace= option. You can include {time} in the file name (e.g. trace=trace-{time}.json).
The pattern {time} is replaced by the time of the program execution represented by the yyyyMMdd-HHmmssSSS format including year, month, day, hour, minute, second, and millisecond. You can also explicitly specify the format like this: {time:yyyyMMdd}. The format string is passed to java.text.SimpleDateFormat class.

It should be noted that SELogger overwrites existing trace files without warnings. Programs executed with the same option (e.g. parallel testing of Maven Surefire Plugin) may accidentally overwrite execution traces recorded by previous executions.

Check a weaving process log

SELogger can produce a log including its internal process (e.g. the order of class loading). You can specify a log file name using the weaverlog= option. The file name also accepts the time pattern, e.g. weaverlog=log-{time}.txt.

Specify an output directory for more details

The output= option specifies a directory to store the entire execution trace.
The directory is automatically created if it does not exist.

The trace file and weaving log file are created in the directory if their file paths are not specified.

Select a Trace Format

The format= option specifies a data format of an execution trace. The default is nearomni format.

• freq mode records only a frequency table of events.
• nearomni mode records the latest event data with timestamp and thread ID for each bytecode location. latest mode is an alias of nearomni.
• omni mode records all the events in a text stream. omnibinary mode records all the events in a binary stream.
  • This option requires an output directory. If output= option is not specified, selogger-output directory is created.
• discard mode discard event data, while it injects logging code into classes.

In the nearomni mode, three additional options are available:

• size= specifies the size of buffers (the number of recorded events per source code location). The default is 32.
  • The nearomni mode creates buffers for each event location. Each buffer consumes SIZE*20 bytes (e.g. 640 bytes in case of the default size). A large buffer size (or a large program) may cause OutOfMemoryError. When SELogger detected OutOfMemory, it records an error message and discards the execution trace to continue the program execution.
• keepobj={strong|weak|id} specifies how to record objects in a trace.
  • (Default) keepobj=strong keeps all objects in recent events.
  • keepobj=weak keeps objects using weak references to avoid the impact to GC. It reduces memory consumption, while some object information may be lost.
  • keepobj=id assigns unique IDs to objects in the same way as format=omni. This option maintains an object-to-id map on memory but may reduce memory consumption. For convenience, string and exception messages are also recorded in the trace file.
  • For compatibility with previous versions of SELogger, keepobj={true|false} is regarded as keepobj={strong|weak}, respectively.
• json={true|false} specifies whether the output file is written in a JSON format or not.
  • The default value is true. If this is set to false, a CSV format is used.

The omni mode records more details about the execution trace. By default, it records the contents of String objects and stack traces of exception objects.

• The string=false option discards the strings.
• The exception=message option records only exception messages.
• The exception=none option disables the recoding of stack traces.

The omni mode also has an additional option to record timestamps of events.

• The timestamp=true option adds a timestamp for each event. Each value is returned by System.currentTimeMilis().

Select Event Types

The default configuration records all events in the list of recordable runtime events. It may slow down an execution significantly. If you are interested in only a subset of the events, you can exclude uninteresting events from logging. This option affects the runtime performance because SELogger does not inject logging code for the excluded events.

The weave= option specifies events to be recorded. Supported event groups are:

• EXEC (entry/exit)
• CALL (call)
• PARAM (parameters for method entries and calls)
• FIELD (field access)
• ARRAY (array creation and access)
• OBJECT (constant object usage)
• SYNC (synchronized blocks)
• LOCAL (local variables)
• LABEL (conditional branches)
• LINE (line numbers)
• ALL (All events listed above)

The event group names EXEC and CALL come from AspectJ pointcut: execution and call.

You can add multiple groups in a single option using + (e.g., weave=EXEC+CALL method execution and call events).

Exclude Utilities and Libraries from Logging

Logging may generate a huge amount of events due to a particular sequence of instructions frequently executed in a loop. You can manually exclude such utility classes from logging by specifying filtering options.

Another reason to exclude some libraries is to avoid breaking library code. As SELogger inserts logging code into classes at runtime, the behavior may break some classes, e.g. those using a custom class loader. For example, SELogger excludes JavaFX classes from logging to avoid crash (NoClassDefFoundError).

You can find a list of loaded classes in the log.txt file generated by SELogger.
A message Weaving executed: [Class Name] loaded from [URI] shows a pair of class name and location.

Filtering by Package and Class Names

Using e= option, you can specify a prefix of class names excluded from the logging process.
You can use multiple e= options to enumerate class paths. By default, the selogger excludes the system classes from logging: sun/,com/sun/, java/, javax/, and javafx/.

If a class is excluded from logging by this filter, a log message Excluded by name filter: (the class name) is recorded in a log file.

If you would like to add logging code to some filte