[Java] Introduction of heartbeat-logger that periodically outputs the method/line number being executed

1 minute read

Problem

There are times when you want to check which process is taking a long time (or is it stopped), such as Java batch processing that takes a long time.

However, when embedding a log during processing, it takes some experience to determine its intuition and granularity. In addition, if it stops for a long time at a specific location, nothing will be output to the log.

solution

I wanted to be able to periodically output information about the line being executed to the log. For this reason, we have created a heartbeat-logger that makes this a very simple project. https://github.com/flyaway2112/heartbeat-logger

Execution result

Even if you do not embed the log sequentially, you can output the log being processed periodically as shown below.

2020-7-01 00:11:23.881 [pool-1-thread-1] DEBUG com.example.LargeBatch-Start heartbeat logger
2020-7-01 00:11:23.883 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess1(LargeBatch.java:22)
2020-7-01 00:11:23.983 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess1(LargeBatch.java:22)
2020-7-01 00:11:24.084 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess2(LargeBatch.java:26)
2020-7-01 00:11:24.185 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess2(LargeBatch.java:26)
2020-7-01 00:11:24.286 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess2(LargeBatch.java:26)
2020-7-01 00:11:24.386 [pool-1-thread-1] INFO com.example.LargeBatch-com.example.LargeBatch.doLargeProcess2(LargeBatch.java:26)
2020-7-01 00:11:24.480 [pool-1-thread-1] DEBUG com.example.LargeBatch-Shutdown heartbeat logger

How to use

SLF4J You can use it from the interface.

Logger generation

HeartBeatLogger logger = HeartBeatLoggerFactory.getLogger(this.getClass(), "com.example", 100);

The first argument of the getLogger method is the LoggerFactpry.getLogger(Class)methodofSLF4J.PasstheclasstobeusedastheLoggernameofSLF4J,aswiththeargumentof.YoucanuseitinthesamewayasGettingLoggerwithSLF4J.

The second argument is the package name (prefix match) to be output to the log as “Processing in progress”. In the case of the above sample, output is traced back to the end of the stack trace and processing of the com.example package. This is a mechanism to prevent the problem that “even if the information of the Java standard class or library method is output, it is not possible to know from which process of the project the process is being executed.” If you pass null, the end of the stack trace is output.

The third argument is the log output interval (milliseconds).

Start and end of processing

try {
  logger.start();
  // Process for log output here
} finally {
  logger.shutdown();
}

From the start method is called until the shutdown method is called, the log is automatically output at the set interval.