IK.AM

@making's tech note

SLF4J互換のrate-limited-loggerを使うメモ

🗃 {Programming/Java/com/swrve/ratelimitedlogger}
🏷 Java 🏷 Spring Boot 🏷 SLF4J 
🗓 Updated at 2023-10-17T13:57:11Z  🗓 Created at 2023-10-17T13:55:36Z   🌎 English Page

https://github.com/Swrve/rate-limited-logger を使うメモ。

以下"rate-limited-loggerの使用"の節以外は次のプロンプトでChatGPTで生成しました。
"ログに対するRate Limitを設定するブログ記事を書こうとしています。ログが多いと収集側のコストが大きくなるという背景から書きはじめてください。"

ログのRate Limit設定: なぜ必要か？

現代のシステムは、毎秒何千、何万というデータを生成し、そのデータの大部分はログとしてシステムの内外に保存されます。これらのログは、エラーの診断、パフォーマンスのモニタリング、セキュリティの監視などのために極めて重要です。しかし、ロギングのコストを考慮せずに無制限にログを生成し続けることは、システムや収集側に大きなコストをもたらす可能性があります。

1. コストの増加

ログの量が増えると、それを収集、保存、分析するためのリソースも増加します。これは、ストレージコスト、ネットワーク帯域、そして処理能力に関わるものです。特にクラウドサービスを使用してログを収集・保存する場合、料金がデータ量やリクエスト数に応じて増加することが多いため、意図せずにコストが増大することが考えられます。

2. 分析の効率低下

ログのノイズが増加すると、実際に問題を特定するための重要な情報を見つけるのが難しくなります。これにより、分析の時間や労力が増大し、迅速な問題解決が困難になる可能性があります。

3. システムのパフォーマンス低下

過剰なログ生成は、アプリケーションやシステムのパフォーマンスにも影響を与える可能性があります。これは、ログ出力に伴うI/O操作の増加や、ロギングプロセスに必要なCPUリソースの消費などに起因します。

Rate Limitの導入

上述のような問題を回避するために、ログの生成や送信にレートリミットを設定することが考えられます。レートリミットを適切に設定することで、不要なログの生成を減少させ、コストとパフォーマンスのバランスを保つことができます。

  • 固定Rate Limit: 一定時間内に生成・送信できるログの最大件数を指定します。
  • 動的Rate Limit: システムの状況や負荷に応じてログの生成・送信レートを変動させます。
  • 優先度ベースのRate Limit: エラーログや警告ログなど、重要度の高いログは優先して取得し、情報ログなどの低い優先度のログの生成や送信を制限します。

rate-limited-loggerの使用

https://github.com/Swrve/rate-limited-logger を使うと固定Rate Limitを簡単に設定できます。SLF4互換なので、既存のアプリに組み込みやすいです。

まずは次のようなSpring MVCのControllerを例に挙げます。

package com.example;

import java.time.Duration;
import java.time.Instant;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {
    private final Logger log = LoggerFactory.getLogger(HelloController.class);

    @GetMapping(path = "")
    public String hello() {
        Instant now = Instant.now();
        log.info("Hello {}", now);
        return "Hello World!";
    }
}

リクエスト毎にinfoログを出力しています。このアプリに対して、例えばabコマンドを使って次のようなリクエストを送ってみます。

ab -n 1000 -c 50 http://localhost:8080/

次のようなログが1000件出力されます

2023-10-17T22:40:21.686+09:00  INFO 82757 --- [nio-8080-exec-1] com.example.HelloController              : Hello 2023-10-17T13:40:21.686454Z
2023-10-17T22:40:21.696+09:00  INFO 82757 --- [nio-8080-exec-2] com.example.HelloController              : Hello 2023-10-17T13:40:21.696639Z
2023-10-17T22:40:21.696+09:00  INFO 82757 --- [nio-8080-exec-6] com.example.HelloController              : Hello 2023-10-17T13:40:21.696694Z
2023-10-17T22:40:21.696+09:00  INFO 82757 --- [nio-8080-exec-3] com.example.HelloController              : Hello 2023-10-17T13:40:21.696673Z
...
2023-10-17T22:40:21.773+09:00  INFO 82757 --- [io-8080-exec-21] com.example.HelloController              : Hello 2023-10-17T13:40:21.773209Z
2023-10-17T22:40:21.773+09:00  INFO 82757 --- [nio-8080-exec-1] com.example.HelloController              : Hello 2023-10-17T13:40:21.773225Z
2023-10-17T22:40:21.773+09:00  INFO 82757 --- [io-8080-exec-23] com.example.HelloController              : Hello 2023-10-17T13:40:21.773188Z
2023-10-17T22:40:21.773+09:00  INFO 82757 --- [io-8080-exec-26] com.example.HelloController              : Hello 2023-10-17T13:40:21.773203Z

このようなログを1件漏らさず保存しておくのが重要なケースもありますし、ただのゴミである場合もあります。 ゴミである場合に、このようなログが全て外部に保存されるのがコストの無駄です。

rate-limited-loggerを使って次のようにコードを書き換えます。

次のコードでは、ロガーの生成部分でrate-limited-loggerのRateLimitedLogがSLF4JのLoggerをラップし、秒間ログ出力数を最大10に制限しています。 RateLimitedLog自身、Loggerインタフェースを実装しているクラスであるため、ログの出力部分のコードは変わっていません。

package com.example;

import java.time.Duration;
import java.time.Instant;

import com.swrve.ratelimitedlogger.RateLimitedLog;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {
    private final Logger delegate = LoggerFactory.getLogger(HelloController.class);

    private final RateLimitedLog log = RateLimitedLog
            .withRateLimit(delegate)
            .maxRate(10).every(Duration.ofSeconds(1))
            .build();

    @GetMapping(path = "")
    public String hello() {
        Instant now = Instant.now();
        log.info("Hello {}", now);
        return "Hello World!";
    }
}

このアプリに対して、先と同じabコマンドを使ってリクエストを送ると、次のようなログが出力されます。

2023-10-17T22:46:04.952+09:00  INFO 84142 --- [nio-8080-exec-1] com.example.HelloController              : Hello 2023-10-17T13:46:04.951680Z
2023-10-17T22:46:04.963+09:00  INFO 84142 --- [nio-8080-exec-3] com.example.HelloController              : Hello 2023-10-17T13:46:04.963721Z
2023-10-17T22:46:04.963+09:00  INFO 84142 --- [nio-8080-exec-5] com.example.HelloController              : Hello 2023-10-17T13:46:04.963873Z
2023-10-17T22:46:04.963+09:00  INFO 84142 --- [nio-8080-exec-6] com.example.HelloController              : Hello 2023-10-17T13:46:04.963943Z
2023-10-17T22:46:04.964+09:00  INFO 84142 --- [nio-8080-exec-4] com.example.HelloController              : Hello 2023-10-17T13:46:04.964012Z
2023-10-17T22:46:04.964+09:00  INFO 84142 --- [nio-8080-exec-9] com.example.HelloController              : Hello 2023-10-17T13:46:04.964171Z
2023-10-17T22:46:04.963+09:00  INFO 84142 --- [nio-8080-exec-7] com.example.HelloController              : Hello 2023-10-17T13:46:04.963874Z
2023-10-17T22:46:04.964+09:00  INFO 84142 --- [nio-8080-exec-2] com.example.HelloController              : Hello 2023-10-17T13:46:04.964046Z
2023-10-17T22:46:04.964+09:00  INFO 84142 --- [nio-8080-exec-8] com.example.HelloController              : Hello 2023-10-17T13:46:04.964024Z
2023-10-17T22:46:04.964+09:00  INFO 84142 --- [io-8080-exec-10] com.example.HelloController              : Hello 2023-10-17T13:46:04.964340Z
2023-10-17T22:46:05.954+09:00  INFO 84142 --- [edLogRegistry-0] com.example.HelloController              : (suppressed 990 logs similar to 'Hello {}' in PT0.989S)

1000件中10件だけログが出力され、990件ドロップされていることがわかります。


Logger の実装の切り替えをDIコンテナに任せたい場合は、次のような定義ができます。

package com.example;

import java.time.Duration;

import com.swrve.ratelimitedlogger.RateLimitedLog;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import org.springframework.beans.factory.InjectionPoint;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Scope;

@Configuration(proxyBeanMethods = false)
public class AppConfig {
    @Bean
    @Scope("prototype")
    public Logger logger(InjectionPoint injectionPoint) {
        Logger logger = LoggerFactory.getLogger(injectionPoint.getMethodParameter().getContainingClass());
        return RateLimitedLog
                .withRateLimit(logger)
                .maxRate(10).every(Duration.ofSeconds(1))
                .build();
    }
}

HelloControllerの実装は次のようになります。

package com.example;

import java.time.Instant;

import org.slf4j.Logger;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {
    private final Logger log;

    public HelloController(Logger log) {
        this.log = log;
    }

    @GetMapping(path = "")
    public String hello() {
        Instant now = Instant.now();
        log.info("Hello {}", now);
        return "Hello World!";
    }
}

まとめ

ログはシステムの健全性を保つために不可欠ですが、無制限に生成し続けることは様々な問題を引き起こす可能性があります。Rate Limitを適切に設定することで、効率的にロギングを行い、コストとパフォーマンスの最適なバランスを保つことができます。

SLF4J互換のrate-limited-loggerを使うことで、既存のアプリケーションに簡単にRate Limitを組み込めることを確認しました。

✒️️ Edit  ⏰ History  🗑 Delete