When coding a loop, we often insert some logging code for debugging or progress monitoring purposes. The following code snippet shows an example:

for (int i = 0; i < invocations.size(); i++) {
  // loop body begin
  ...
  // loop body end
  System.out.println("current index: "+i); // pure java
  currentTimeInMs = ...;
  if (currentTimeInMs % 1000 == 0) {  // log every econd
    logger.debug("current index: {}", i);    // slf4j
  }
}

Disadvantages of the Naive Approach

However, this approach has some disadvantages. First, the logging code is executed by the same thread which executes the loop body. If the logging code causes an exception, for example, due to a NullPointerException, the execution of the loop body is interrupted. Thus, the execution of the application can break because of some fault in the logging code.

Moreover, the executing thread is thwarted by the addtional logging code. Remember that executing I/O operations, like printing to the console or to a file, is slower by several orders of magnitude. Especially for performance critical code regions, this approach is not recommended.

Finally, the logging code is executed in each and every iteration of the loop although it is often sufficient to log the loop’s state every second or every minute. If you now think of a solution similar to the one shown above in Line 5, then remember that this additional if statement causes even more runtime overhead and further increases the potential for errors.

A Better Approach

A less intrusive, less error-prone, and faster approach is the following. First, we declare a volatile field progressIndex which represents the current index of the loop we want to monitor. For this purpose, we update the value of this field as shown in the following code snippet. We do not insert our original logging code here.

for (int i = 0; i < invocations.size(); i++) {
    progressIndex = i;
    // loop body
}

Instead, we create an additional thread which executes our logging code now. This thread performs a do-while loop as shown in the following code snippet from Line 7 to Line 28. We use `Thread.sleep()` to implement a user-defined time interval (here: 1000 ms). The thread reads the current index of the loop under monitoring indicated by the variable progressIndex in Line 13. As we declared it as volatile, it is synchronized between our new monitoring thread and the application thread(s). We cache the progressIndex as local variable, since the value of this variable can change on each subsequent read-access. In this way, the value is consistent within an iteration of the do-while loop.

To avoid interfering with the application, we declare our new monitoring thread as a deamon. In this way, the thread is automatically terminated by the JVM when all application threads have terminated.

The rest of the do-while loop computes the remaining execution time of the application and executes the domain-specific logging code. In this example, we print out the current number of NoSql queries which were already executed by the application loop.

Thread progressMonitoringThread = new Thread(new Runnable() {
    @Override
    public void run() {
        long lastTimestamp = System.currentTimeMillis();
        int lastProgressIndex = progressIndex;
        
        do {
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                throw new IllegalStateException(e);
            }
            final int localProgressIndex = progressIndex;
            
            long currentTimestamp = System.currentTimeMillis();
            long durationInMs = currentTimestamp - lastTimestamp;
            int count = localProgressIndex - lastProgressIndex;
            if (count <= 0) continue;
            long durationInMsPerElement = durationInMs / count;
            
            long remainingDurationInMs = durationInMsPerElement * (numQueries - (localProgressIndex + 1));
            String message = String.format("Executing query %s/%s (%s sec. remaining)", localProgressIndex + 1,
            numQueries, Duration.ofMillis(remainingDurationInMs).getSeconds());
            System.out.println(message);
            
            lastTimestamp = currentTimestamp;
            lastProgressIndex = localProgressIndex;
        } while (progressIndex < numQueries);
    }
});
progressMonitoringThread.setDaemon(true);

progressMonitoringThread.start()

This approach does not break the execution of the application if the logging code is faulty. In the worst case, our monitoring thread terminates – no interfering with the application. Moreover, the runtime overhead is reduced to a minimum. We only set the progressIndex in each iteration of the application loop. Finally, the approach allows to log the state of the loop at a user-defined time interval. We are not forced to log it on each iteration anymore. Hence, we have changed the type of notification from an event-driven style to a time-driven style.