Code Instrumentation for Logging

This document explains how to add logging and tracing to MicroEJ applications and libraries with three different solutions. The aim is to help developers to report precise execution context for further debugging and monitoring.

Introduction

One straightforward way to add logs in Java code is to use the Java basic print methods: System.out.println(…).

However, this is not desirable when writing production-grade code, where it should be possible to adjust the log level:

• without having to change the original source code,

• at build-time or at runtime, as application logging will affect memory footprint and performances

Overview

This documentation describes 3 ways for logging data:

• Using Trace library: a real-time event recording library designed for performance and interaction analysis.

• Using Message library: a lightweight and simple logging library.

• Using Logging library: a complete and highly configurable standard logging library.

The use of each library will be illustrated by instrumenting the following code snippet:

public class Main {

   enum ApplicationState {
      INSTALLED, STARTED, STOPPED, UNINSTALLED
   }

   private static ApplicationState currentState;
   private static ApplicationState previousState;

   public static void main(String[] args) {
      currentState = ApplicationState.UNINSTALLED;
      switchState(ApplicationState.INSTALLED);
   }

   public static void switchState(ApplicationState newState) {
      previousState = currentState;
      currentState = newState;
   }
}

Finally, the last section describes some techniques to remove logging related code in order to reduce the memory footprint.

Log with the Trace Library

The ej.api.trace Trace library provides a way of tracing integer events. Its features and principles are described in the Event Tracing section.

Here is a short example of how to use this library to log the entry/exit of the switchState() method:

1. To use this library, add the following line to the project build file:

   Gradle (build.gradle.kts)MMM (module.ivy)

   implementation("ej.api:trace:1.1.1")
   

2. Start by initializing a Tracer object:

   private static final Tracer tracer = new Tracer("Application", 100);
   

   In this case, Application identifies a category of events that defines a maximum of 100 different event types.

3. Next, start trace recording:

   public static void main(String[] args) {
      Tracer.startTrace();
   
      currentState = ApplicationState.UNINSTALLED;
      switchState(ApplicationState.INSTALLED);
   }
   

4. Use the methods Tracer.recordEvent(…) and Tracer.recordEventEnd(…) to record the entry/exit events in the method:

   private static final int EVENT_ID = 0;
   
   public static void switchState(ApplicationState newState) {
      tracer.recordEvent(EVENT_ID);
   
      previousState = currentState;
      currentState = newState;
   
      tracer.recordEventEnd(EVENT_ID);
   }
   

   The Tracer object records the entry/exit of method switchState with event ID 0.

5. Finally, to enable the MicroEJ Core Engine trace system, set the core.trace.enabled option to true.

This produces the following output:

[TRACE: Application] Event 0x0()
[TRACE: Application] Event End 0x0()

Note

The default VEE Port implementation of the Trace library prints the events to the console. See VEE Port Implementation for other available implementations such as SystemView tool.

Log with the Message Library

The ej.library.runtime.message Message library was designed to enable logging while minimizing RAM/ROM footprint and CPU usage. For that, logs are based on message identifiers, which are stored on integers instead of using of constant Strings. In addition to a message identifier, the category of the message allows the user to find the corresponding error/warning/info description. An external documentation must be maintained to describe all message identifiers and their expected arguments for each category.

Principles:

• The MessageLogger type allows for logging messages solely based on integers that identify the message content.

• Log a message by using methods MessageLogger.log(…) methods, by specifying the log level, the message category, and the message identifier. Use optional arguments to add any useful information to the log, such as a Throwable or contextual data.

• Log levels are very similar to those of the Logging library. The class ej.util.message.Level lists the available levels.

• Loggers rely on the MessageBuilder type for message creation. The messages built by the BasicMessageBuilder follow this pattern: [category]:[LEVEL]=[id]. The builder appends the specified Object arguments (if any) separated by spaces, then the full stack trace of the Throwable argument (if any).

• The FilterMessageLogger allows to filter messages actually logged based on a threshold level (defaults to INFO). The threshold level can be modified dynamically with FilterMessageLogger.setLevel(). Use the system FilterMessageLogger.INSTANCE or create a new logger to configure the level of logged messages per instance.

Here is a short example of how to use this library to log the entry/exit of the switchState() method:

1. To use this library, add the following line to the project build file:

   Gradle (build.gradle.kts)MMM (module.ivy)

   implementation("ej.library.runtime:message:2.2.1")
   

2. Call the message API to log some info:

   private static final String LOG_CATEGORY = "Application";
   
   private static final int LOG_ID = 2;
   
   public static void switchState(ApplicationState newState) {
      previousState = currentState;
      currentState = newState;
   
      FilterMessageLogger.INSTANCE.log(Level.INFO, LOG_CATEGORY, LOG_ID, previousState, currentState);
   }
   

This produces the following output:

Application:I=2 UNINSTALLED INSTALLED

Log with the Logging Library

The ej.library.eclasspath.logging Logging library implements a subset of the standard Java java.util.logging package and follows the same principles:

• There is one instance of LogManager by application that manages the hierarchy of loggers.

• Find or create Logger objects using the method Logger.getLogger(String). If a logger has already been created with the same name, this logger is returned, otherwise a new logger is created.

• Each Logger created with this method is registered in the LogManager and can be retrieved using its String ID.

• A minimum level can be set to a Logger so that only messages that have at least this level are logged. The class java.util.logging.Level lists the available standard levels.

• The Logger API provides multiple methods for logging:

  • log(…) methods that send a LogRecord to the registered Handler instances. The LogRecord object wraps the String message and the log level.

  • Log level-specific methods, like severe(String msg), that call the aforementioned log(...) method with the correct level.

• The library defines a default Handler implementation, called DefaultHandler, that prints the message of the LogRecord on the standard error output stream. It also prints the stack trace of the Throwable associated with the LogRecord if there is one.

Here is a short example of how to use this library to log the entry/exit of the switchState() method:

1. To use this library, add the following line to the project build file:

   Gradle (build.gradle.kts)MMM (module.ivy)

   implementation("ej.library.eclasspath:logging:1.2.1")
   

2. Call the logging API to log some info text:

   public static void switchState(ApplicationState newState) {
      previousState = currentState;
      currentState = newState;
   
      Logger logger = Logger.getLogger(Main.class.getName());
      logger.log(Level.INFO, "The application state has changed from " + previousState.toString() + " to "
            + currentState.toString() + ".");
   }
   

This produces the following output:

main INFO: The application state has changed from UNINSTALLED to INSTALLED.

Note

Unlike the two other libraries discussed here, the Logging library is entirely based on Strings (log IDs and messages). String operations can lead to performance issues and String objects use significant ROM space. When possible, prefer using a logging solution that uses primitive types over Strings.

Remove Logging Related Code

This section describes some techniques to remove logging related code, which saves memory footprint when logging is disabled at runtime. This is typically useful when building two Firmware flavors: one for production and one for debug.

Wrap with a Constant If Statement

A boolean constant declared in an if statement can be used to fully remove portions of code. When this boolean constant is detected to be false, the wrapped code becomes unreachable and is not embedded.

Note

More information about the usage of constants and if code removal can be found in the Classpath section.

1. Let’s consider a constant com.mycompany.logging declared as false in a resource file named example.constants.list.

2. Wrap the log code by an if statement, as follows:

   private static final String LOG_PROPERTY = "com.mycompany.logging";
   
   public static void switchState(ApplicationState newState) {
      previousState = currentState;
      currentState = newState;
   
      if (Constants.getBoolean(LOG_PROPERTY)) {
         Logger logger = Logger.getLogger(Main.class.getName());
         logger.log(Level.INFO, "The application state has changed from " + previousState.toString() + " to "
            + currentState.toString() + ".");
      }
   }
   

When using the Trace API (Trace), you can use the Tracer.TRACE_ENABLED_CONSTANT_PROPERTY constant that represents the value of the core.trace.enabled option.

Follow the same principle as before:

private static final int EVENT_ID = 0;

public static void switchState(ApplicationState newState) {
   if (Constants.getBoolean(Tracer.TRACE_ENABLED_CONSTANT_PROPERTY)) {
      tracer.recordEvent(EVENT_ID);
   }

   previousState = currentState;
   currentState = newState;

   if (Constants.getBoolean(Tracer.TRACE_ENABLED_CONSTANT_PROPERTY)) {
      tracer.recordEventEnd(EVENT_ID);
   }
}

Shrink Code Using ProGuard

ProGuard is a tool that shrinks, optimizes, and obfuscates Java code.

It optimizes bytecode as well as it detects and removes unused instructions. Therefore it can be used to remove log messages in a production binary.

A dedicated How-To is available at https://github.com/MicroEJ/How-To/tree/master/Proguard-Get-Started. It describes how to configure ProGuard to remove elements of code from the Logging library.