vlambda博客
学习文章列表

如何在log4j中打印时间精确到纳秒

排查生产问题时出现了同一毫秒下四条日志,无法分清先后顺序,因此有了需要精确到纳秒的需求。

好在之前对jdk8的LocalTime有所了解,知道可以取到纳秒,激动输出。

LocalTime.now().getNano();

结果却和所想不太一样,当前时间2021-07-20 18:38:02,929,输出却是929000000,后面的六位去哪了。进一步跟踪LocalTime.now()发现使用到了Clock类进行创建。

public static LocalTime now(Clock clock) {
Objects.requireNonNull(clock, "clock");
// inline OffsetTime factory to avoid creating object and InstantProvider checks
final Instant now = clock.instant(); // called once
ZoneOffset offset = clock.getZone().getRules().getOffset(now);
long localSecond = now.getEpochSecond() + offset.getTotalSeconds(); // overflow caught later
int secsOfDay = (int) Math.floorMod(localSecond, SECONDS_PER_DAY);
return ofNanoOfDay(secsOfDay * NANOS_PER_SECOND + now.getNano());
}

而在Clock类的注解上发现,Clock的精度是不能保证的,不一定能到纳秒。

 * @implNote
* The clock implementation provided here is based on {@link System#currentTimeMillis()}.
* That method provides little to no guarantee about the accuracy of the clock.
* Applications requiring a more accurate clock must implement this abstract class
* themselves using a different external clock, such as an NTP server.

因此我们需要自己实现一个NanoClock

public class NanoClock extends Clock
{
private final Clock clock;

private final long initialNanos;

private final Instant initialInstant;

public NanoClock()
{
this(Clock.systemUTC());
}

public NanoClock(final Clock clock)
{
this.clock = clock;
initialInstant = clock.instant();
initialNanos = getSystemNanos();
}

@Override
public ZoneId getZone()
{
return clock.getZone();
}

@Override
public Instant instant()
{
return initialInstant.plusNanos(getSystemNanos() - initialNanos);
}

@Override
public Clock withZone(final ZoneId zone)
{
return new NanoClock(clock.withZone(zone));
}

private long getSystemNanos()
{
return System.nanoTime();
}
}

使用自己的Clock就可以精确输出纳秒了。

Clock nanoClock = new NanoClock();
long NANOTIME = LocalTime.now(nanoClock).getNano();

有了纳秒之后,我们想要通过自定义pattern参数进行输出。

首先自定义PatternConverter

@Plugin(name = "NanoPatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "y" })
public class NanoPatternConverter extends LogEventPatternConverter {
private Clock nanoClock = new NanoClock();
private static final NanoPatternConverter INSTANCE =
new NanoPatternConverter();

public static NanoPatternConverter newInstance(
final String[] options) {
return INSTANCE;
}

private NanoPatternConverter(){
super("NanoPatternConverterName", "NanoPatternConverterStyle");
}

@Override
public void format(LogEvent event, StringBuilder toAppendTo) {
Clock nanoClock = new NanoClock();
long NANOTIME = LocalTime.now(nanoClock).getNano();
toAppendTo.append(NANOTIME);
}
}

原项目中采用的是xml方式配置。在log4j2.xml中追加

1. 定义参数转换器的包名,添加为Configuration的属性。

packages="自定义参数转换器的包名"

自己调试的时候这里犯了一个很低级的错误,一直写成了类的全限定名,怎么也没看出问题,注意是包名。    2.  添加自定义参数

<Property name="Nano">%y</Property>

    3. 使用自定义参数

<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="${Nano}"/>
</Console>
2021-07-20 19:04:20,717 DEBUG  - 716928173
2021-07-20 19:04:20,717 DEBUG - 717079760
2021-07-20 19:04:20,717 DEBUG - 717247531

大成功!