problem

There are times when you want to see which process is taking a long time (or is stopped), such as in a time-consuming Java batch process.

However, when embedding a log during processing, it takes some experience to determine the point and granularity. Also, if you stop at a specific point for a long time, nothing will be output to the log.

solution

I wanted to be able to log information about running rows on a regular basis. For this reason, it's a very simple project, but I created heartbeat-logger to do this. https://github.com/flyaway2112/heartbeat-logger

Execution result

Even if you do not embed the sequential log, you can periodically output the log being processed 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 It can be used from a like interface.

Logger generation

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

The first argument of the getLogger method is the SLF4J LoggerFactpry.getLogger (Class) method. As with the argument of, pass the class to be used as the Logger name of SLF4J. You can use it in the same way as When acquiring Logger with SLF4J.

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, it is output to the log from the end of the stack trace to the processing of the com.example package. This is a mechanism to prevent the problem that "even if the method information of Java standard class or library is output, it is not known from which process of the project it is being executed". If null is passed, the end of the stack trace will be output.

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

Start and end of processing

try {
  logger.start();
  //Processing of log output target here
} finally {
  logger.shutdown();
}

From the time you call the start method to the time you call the shutdown method, the log is automatically output at the set interval.