

Relative Nanoseconds Appender¶

LoggingEvent already has a timestamp associated with it, but that timestamp is generated by System.currentTimeMillis. For most appenders, this would be fine, but appending to ringbuffer is so fast that several events can be appended in the same millisecond, exceeding the resolution and making direct time comparison difficult when those records are dumped to JDBC. Adding a relative_ns field provides resolution down to the nanosecond, sort of.

For example, here's two different records with the same millisecond.

{"id":"FfwJtsNLLWo6O0Qbm7EAAA","relative_ns":11808036,"tse_ms":1584163603315,"start_ms":null,"@timestamp":"2020-03-14T05:26:43.315Z","@version":"1","message":"HikariPool-2 - Start completed.","logger_name":"com.zaxxer.hikari.HikariDataSource","thread_name":"play-dev-mode-akka.actor.default-dispatcher-7","level":"INFO","level_value":20000}
{"id":"FfwJtsNLLWo6O0Qbm7EAAB","relative_ns":11981656,"tse_ms":1584163603315,"start_ms":null,"@timestamp":"2020-03-14T05:26:43.315Z","@version":"1","message":"jdbc-appender-pool-1584163602961 - Start completed.","logger_name":"com.zaxxer.hikari.HikariDataSource","thread_name":"logback-appender-ASYNC_JDBC-2","level":"INFO","level_value":20000}

Note that the timestamp is 2020-03-14T05:26:43.315Z and the time since epoch is 1584163603315. The flake ids distinguish between log entries by using a counter when millisecond precision is exceeded, so the first record is FfwJtsNLLWo6O0Qbm7EAAA ending in A and the second record is FfwJtsNLLWo6O0Qbm7EAAB ending in B. The relative time tells us exactly how much time has elapsed between the two events: 11981656 - 11808036 is 0.17362 milliseconds.

All logging events are computed using System.nanoTime - NanoTime.start, where NanoTime.start is a static final field initialized JVM start time (technically at class loading but close enough). This value may be negative to begin with, but always increments.

See the showcase for an example.

Usage¶

 <appender class="com.tersesystems.logback.classic.NanoTimeComponentAppender">
    <appender ...>

    </appender>
</appender>

You can extract the nanotime using a converter:

<!-- available as "%nanoTime" in a pattern layout -->
<conversionRule conversionWord="nanoTime"
                    converterClass="com.tersesystems.logback.classic.NanoTimeConverter" />

There are no configuration options.