Rate Limited Logging

Proper logging is an essential part of any production system. For instance, in the case of an exception, you might want to log the state of some variables and the stacktrace.

If you have ever considered adding logging to your code but then decided not to do it because you were afraid that it would log too often / too much data, then this article will be useful to you as it explains how to use a rate limited logger.

Setting Up a Project

Clone the project: rate-limited-logger.

Rate limited logging

Logging is useful. If you’re on a modern system, you might be able to change the configuration at runtime, enabling or disabling (certain) logging dynamically. Or change the log level during runtime, for instance using Spring Boot actuator . Or you might even use something like GCP Cloud Debugger, where you can inject log statements during runtime.

But still, many of us need to do at least a configuration change, rebuild the deployment unit and deploy it in order to make such changes. It is doable but it does take time.

With a rate limited logger you can add log statements and specify how many times at the most you want the log statement to be logged with a given timeframe. That should allow you to be more generous with you log statements as there is a limit to the amount of output generated.

Initializing and using the logger

The following code initializes the logger to emit maximally three statements per three-second time period. It is that simple.

 1public class RateLimitedLoggerDemo {
 2  private static final Logger logger = LoggerFactory.getLogger(RateLimitedLoggerDemo.class);
 3  
 4  private static final RateLimitedLog rateLimitedLog =
 5  RateLimitedLog.withRateLimit(logger).maxRate(3).every(Duration.ofSeconds(3)).build();
 6
 7  // other code
 8  private void someMethod() {
 9    // use logger
10    rateLimitedLog.info("The time is: {}", LocalTime.now());
11  }
12}

Demo

This example is available in the Github project .

 1  public static void main(String[] args) throws InterruptedException {
 2      rateLimitedLog.info("The time is: {}", LocalTime.now());
 3      rateLimitedLog.info("The time is: {}", LocalTime.now());
 4      rateLimitedLog.info("The time is: {}", LocalTime.now());
 5      // The following gets does _not_ get emitted
 6      rateLimitedLog.info("The time is: {}", LocalTime.now());
 7      Thread.sleep(3000);
 8      // Time span has elapsed, it will again log
 9      rateLimitedLog.info("After sleep");
10      rateLimitedLog.info("The time is: {}", LocalTime.now());
11  }

It prints something like this, depending on the time of day:

1[main] INFO dk.anno1980.RateLimitedLoggerDemo - The time is: 16:19:10.896737
2[main] INFO dk.anno1980.RateLimitedLoggerDemo - The time is: 16:19:10.983371
3[main] INFO dk.anno1980.RateLimitedLoggerDemo - The time is: 16:19:10.983561
4[RateLimitedLogRegistry-0] INFO dk.anno1980.RateLimitedLoggerDemo - (suppressed 1 logs similar to 'The time is: {}' in PT2.954S)
5[main] INFO dk.anno1980.RateLimitedLoggerDemo - After sleep
6[main] INFO dk.anno1980.RateLimitedLoggerDemo - The time is: 16:19:13.985349

As can be seen, only four lines with the pattern The time is: {} is printed. The last fourth statement in the code is rate limited. This is also visible by the presence of the line: [RateLimitedLogRegistry-0] INFO dk.anno1980.RateLimitedLoggerDemo - (suppressed 1 logs similar to 'The time is: {}' in PT2.954S) which tells that given pattern was suppressed 1 time in a given time span.

Things to remember

• A rate limit is applied per pattern and level, see this example showing that this is true for a given pattern and this one for levels .
• The info method above does some work behind the scenes. It looks up the logger in a concurrent map and then in an array for the level. You can minimize these operations by doing them once, as exemplified here .
• The rate limiting applies per JVM. If you have ten instances of your application running, you will have ten different rate limiters running. If the logs are sent to Splunk or something similar, this means you might see more output than you initially thought (not you specifically of course :) ).