Microsecond time-stamp logging for MiFID II

From 3 January 2018, the Markets in Financial Instruments Directive II (MiFID II) introduces new requirements for the granularity of transaction-event time-stamps.

This means that under certain circumstances an application will record timestamps to a granularity of 1 microsecond: the finest granularity specified under MiFID II.

Microsecond timestamping

According to the MiFID II regulatory technical and implementing standards if your software falls under the “high frequency trading” definition, logging needs to be to microsecond resolution, and needs to be synchronised to within 100 microseconds of UTC.

Problem

Java 8 does not provide microsecond time stamping, it only implements the Clock interface with millisecond resolution.  So even when you try to get nanoseconds from java.time classes they will just return zeros.

Solutions

We looked at different approaches to support microsecond time-stamps in our log files.

1. With Java 9 a new implementation of Clock is available with nanosecond resolution and the actual time-stamp depends on the underlying hardware. However our customers  might not be able or want to upgrade their systems and infrastructure to the latest Java version just yet. Another aspect is that we would have to wait until different logging API’s implement their logging time-stamps with the new Java 9 Clock.
2. You could calculate elapsed time by using System.nanoTime() but this approach is not accurate and it is actually only useful comparing two different nano times to see how long something took.
3. Our Caplin platform team has written a JNI library for nanosecond accuracy time-stamps that provides a com.caplin.time.NanoClock class.

An opensource version of the nanotime library is available on GitHub. It implements a JNI wrapper for a C Clock implementation.

Using nanotime library with log4j

I was using the nanotime library in one of our Applications enable log4j to display microseconds and nanoseconds in the logging timestamp. I needed to extend log4j2 to enable microseconds time-stamping for logging. I added a PatternConverters plugin that allowed me to add a %nano tag. I then can use the %nano tag in the log4j2 configuration file. The implementation of the PatternConverters uses the com.caplin.time.NanoClock class available through the datasource library, as shown in the following example.

@Plugin(name = "NanoTimeConverter", category = "Converter")
@ConverterKeys({"nano"})
public final class NanoTimeConverter extends LogEventPatternConverter {
  private final String[] options;
  private final NanoClock nanoClock;

  public NanoTimeConverter(String[] options) {
    super("NanoTimeConverter", "nano");
    this.options = options;        // add some options if needed
    nanoClock = new NanoClock();  // instantiate your own nano clock
  }

  public static NanoTimeConverter newInstance(final String[] options) {
    return new NanoTimeConverter(options);
  }

  @Override
  public void format(LogEvent event, StringBuilder toAppendTo) {

    synchronized (this) {
      final int nano = nanoClock.instant().getNano();
      Iterable result = Splitter.fixedLength(3).split(String.valueOf(nano));
      String[] nanoParts = Iterables.toArray(result, String.class);

      //String milliSecond= nanoParts[0];
      String microSecond = nanoParts.length >= 2 ? nanoParts[1]: "000";
      String nanoSecond = nanoParts.length >= 3 ? nanoParts[2]: "000";
      toAppendTo.append(microSecond+"."+nanoSecond);
    }
  }
}

And the corresponding log4j2.xml configuration file.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" packages="you.package">
    <Properties>
      <Property name="log4j.Clock">your.package.LogNanoClock</Property>
   </Properties>
   <Appenders>
      <!-- This logs all log messages -->
      <RollingFile name="all" fileName="logFileName.log" filePattern="logFileName-%i.log.gz">
         <PatternLayout pattern="%d{yyyy/MM/dd-HH:mm:ss.SSS}.%nano %d{Z}:   \(%thread\): %5level: %logger{36}: %msg%n"/>
         <Policies>
            <SizeBasedTriggeringPolicy size="500 MB"/>
         </Policies>
         <DefaultRolloverStrategy max="50"/>
      </RollingFile>
   </Appenders>
   <Loggers>
      <Root level="info">
         <AppenderRef ref="all"/>
      </Root>
   </Loggers>
</Configuration>

First for my Converter to be picked up I had to add the packages property to the configuration. Then I added %nano to my pattern configuration. I actually split the date pattern in the middle to put my nano pattern in between.

Now I have a timestamp with nanotime precision in my log  with the following format: yyyy/MM/dd-HH:mm:ss.SSS.microseconds.nanoseconds +timezone.

Open issue

After I checked my logs I realised that the millisecond time-stamp used by the standard date formatter and the one use by the NanoClock can still be different by some milliseconds. This is because log4j creates the timestamp when the LogEvent is created and the NanoClock.Instant is created when the converter is called. One solution could be to only use the timestamp from the NanoClock.Instant.toString method but this will mean there a delay caused by the logging of some milliseconds. Another option might be to instantiate log4j with your own implementation of org.apache.logging.log4j.core.util.Clock which is using the same NanoClock used by this Converter.