Spring Boot Actuatorで、Micrometerで収集したメトリクスをログに出力する

これは、なにをしたくて書いたもの？

Spring Bootには、Spring Boot ActuatorおよびMicrometerを使うことでメトリクスをモニタリングシステムで収集することが
できます。

ここで、収集先のモニタリングシステムがない場合にログ出力でもできないかな？と思って調べてみたら、Micrometerの
LoggingMeterRegistryを使えばできそうだったので、試してみました。

Spring Boot ActuatorとMicromter

先に、Spring Boot ActuatとMicrometerについて少し書いておきましょう。

Spring Boot Actuatorは、プロダクション環境でアプリケーションをモニタリング、管理するための機能を提供するものです。

Spring Boot Actuator: Production-ready Features

Spring Boot Actuatorは、spring-boot-starter-actuatorを依存関係に含めることで有効になります。

このうちメトリクスに関する機能は、Micrometerを統合することで実現しています。

Metrics

Micrometer Application Monitoring

Datadog、New Relic、Elasticsearchなど、いろいろなモニタリングシステムにメトリクスを送信できたりします。

Supported monitoring systems

利用するには、対象のモニタリングシステムに関するmicrometer-registry-xxxxxを依存関係に加え、設定を行えばOKです。

LoggingMeterRegistry

モニタリングシステムがない場合に、簡単に動作確認する方法はないかな？と思ったのですが。

Micrometerのメトリクス登録先であるMeterRegistryの実装として

MeterRegistry (micrometer-core 1.6.6 API)

メトリクスをログ出力するLoggingMeterRegistryというものがあったので、こちらを使ってみましょうというのが
今回のお題です。

LoggingMeterRegistry (micrometer-core 1.6.6 API)

Spring Bootの場合、Spring Boot Actuatorを有効（spring-boot-starter-actuatorを依存関係に含める）うえで、
LoggingMeterRegistryをBean登録すればそれだけで使えます。

    @Bean
    public MeterRegistry meterRegistry() {
        return new LoggingMeterRegistry();
    }

ログの出力先ですが、デフォルトではSLF4Jが利用できる場合はSLF4Jへ、そうでない場合はJava標準のロガー（j.u.l.Logger）に
渡されます。

https://github.com/micrometer-metrics/micrometer/blob/v1.6.6/micrometer-core/src/main/java/io/micrometer/core/util/internal/logging/InternalLoggerFactory.java#L56-L67

https://github.com/micrometer-metrics/micrometer/blob/v1.6.6/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java#L66

メトリクスは定期的に出力されますが、デフォルトだと1分間隔です。

このあたりは、設定することもできます。

LoggingRegistryConfig (micrometer-core 1.6.6 API)

お題

Spring Boot Actuatorを有効にした、簡単なCommandLineRunnerで一定時間動き続けるアプリケーションを作成します。

この時、メトリクスをログ出力します。

あと、追加のメトリクスがなにもないのもなんなので、キャッシュを有効にしてそちらも加えましょう。

環境

今回の環境は、こちらです。

今回は

$ java --version
openjdk 11.0.11 2021-04-20
OpenJDK Runtime Environment (build 11.0.11+9-Ubuntu-0ubuntu2.20.04)
OpenJDK 64-Bit Server VM (build 11.0.11+9-Ubuntu-0ubuntu2.20.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.8.1 (05c21c65bdfed0f71a2f2ada8b84da59348c4c5d)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 11.0.11, vendor: Ubuntu, runtime: /usr/lib/jvm/java-11-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-72-generic", arch: "amd64", family: "unix"

Spring Bootは2.4.5、Spring Frameworkは5.3.6、Micrometerは1.6.6を使用します。

プロジェクトの作成

依存関係にactuatorとcacheを加えて、Spring Bootプロジェクトを作成。

$ curl -s https://start.spring.io/starter.tgz \
  -d bootVersion=2.4.5 \
  -d javaVersion=11 \
  -d name=metrics-logging \
  -d groupId=org.littlewings \
  -d artifactId=metrics-logging \
  -d version=0.0.1-SNAPSHOT \
  -d packageName=org.littlewings.spring.metrics \
  -d dependencies=actuator,cache \
  -d baseDir=metrics-logging | tar zxvf -


$ cd metrics-logging

キャッシュはCaffeineを使うことにしましょう。依存関係に追加しておきます。

 <properties>
        <java.version>11</java.version>
    </properties>
    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-cache</artifactId>
        </dependency>

        <dependency>
            <groupId>com.github.ben-manes.caffeine</groupId>
            <artifactId>caffeine</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

あと、生成されたクラスは使わないので削除しておきます…。

アプリケーションを作成する

それでは、アプリケーションを作成します。

キャッシュも使うので、まずは設定ファイルから。

src/main/resources/application.properties

spring.cache.cache-names=caffeineCache
spring.cache.caffeine.spec=maximumSize=100,recordStats

Caffeineを使ってメトリクスを収集しようと思った場合、recordStatsを有効にしておく必要があります。

キャッシュヒットしなかった場合は、スリープするクラスを作成。

src/main/java/org/littlewings/spring/metrics/MessageService.java

package org.littlewings.spring.metrics;

import java.util.concurrent.TimeUnit;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.cache.annotation.Cacheable;
import org.springframework.stereotype.Service;

@Service
public class MessageService {
    Logger logger = LoggerFactory.getLogger(MessageService.class);

    @Cacheable("caffeineCache")
    public String message(int num) {
        try {
            logger.info("sleeping...");
            TimeUnit.SECONDS.sleep(5L);
        } catch (InterruptedException e) {
            // ignore
        }

        return String.format("Hello %d", num);
    }
}

利用＋起動クラス側。

src/main/java/org/littlewings/spring/metrics/App.java

package org.littlewings.spring.metrics;

import java.sql.Time;
import java.time.Duration;
import java.util.Random;
import java.util.concurrent.TimeUnit;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.CommandLineRunner;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.cache.annotation.EnableCaching;

@SpringBootApplication
@EnableCaching
public class App implements CommandLineRunner {
    Logger logger = LoggerFactory.getLogger(App.class);

    MessageService messageService;

    public static void main(String[] args) {
        SpringApplication.run(App.class, args);
    }

    public App(MessageService messageService) {
        this.messageService = messageService;
    }

    @Override
    public void run(String... args) throws Exception {
        Duration limit = Duration.ofMinutes(2L);

        long startTime = System.currentTimeMillis();
        long elapsedTime = System.currentTimeMillis() - startTime;

        int randomLimit = 50;

        Random random = new Random();
        random.nextInt(randomLimit);

        logger.info("start");

        while (Duration.ofMillis(elapsedTime).minus(limit).isNegative()) {
            logger.info("get message = {}", messageService.message(random.nextInt(randomLimit)));

            TimeUnit.SECONDS.sleep(1L);

            elapsedTime = System.currentTimeMillis() - startTime;
        }

        logger.info("end");
    }
}

先ほど作成したクラスを、Randomを使って2分間適当に呼び出します。

ランダムでキャッシュにヒットするだろう、と。

あとは、LoggingMeterRegistryをBeanとして登録して完了です。

src/main/java/org/littlewings/spring/metrics/MetricsConfig.java

package org.littlewings.spring.metrics;

import java.time.Duration;

import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.logging.LoggingMeterRegistry;
import io.micrometer.core.instrument.logging.LoggingRegistryConfig;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class MetricsConfig {
    @Bean
    public MeterRegistry meterRegistry() {
        return new LoggingMeterRegistry();
    }
}

パッケージングして

$ mvn package

実行。

$ java -jar target/metrics-logging-0.0.1-SNAPSHOT.jar

起動後、こんな感じで動いていきますが

2021-05-03 22:30:16.479  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : start
2021-05-03 22:30:16.509  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:21.515  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 13
2021-05-03 22:30:22.519  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:27.520  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 32
2021-05-03 22:30:28.521  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:33.522  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 4
2021-05-03 22:30:34.523  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:39.524  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 9
2021-05-03 22:30:40.525  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:45.526  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 42
2021-05-03 22:30:46.529  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 9
2021-05-03 22:30:47.530  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:52.531  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 29
2021-05-03 22:30:53.531  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...
2021-05-03 22:30:58.533  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 34
2021-05-03 22:30:59.534  INFO 43396 --- [           main] o.l.spring.metrics.MessageService        : sleeping...

1分経過すると、メトリクスがログ出力されます。

2021-05-03 22:31:16.207  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=hit} throughput=0.016667/s
2021-05-03 22:31:16.207  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=miss} throughput=0.166667/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.memory.allocated{} throughput=2.45 MiB/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.memory.promoted{} throughput=9.022396 KiB/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : logback.events{level=info} throughput=0.433333 events/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.size{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache} value=9
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.count{id=mapped} value=0 buffers
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.count{id=direct} value=1 buffers
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.memory.used{id=direct} value=8 KiB
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.memory.used{id=mapped} value=0 B
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.total.capacity{id=direct} value=8 KiB
2021-05-03 22:31:16.209  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.total.capacity{id=mapped} value=0 B
2021-05-03 22:31:16.210  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.classes.loaded{} value=4808 classes
2021-05-03 22:31:16.210  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.live.data.size{} value=0 B
2021-05-03 22:31:16.210  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.max.data.size{} value=3.888672 GiB
2021-05-03 22:31:16.210  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Old Gen} value=94 MiB
2021-05-03 22:31:16.210  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Eden Space} value=151 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=Compressed Class Space} value=2.75 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'profiled nmethods'} value=6.875 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'non-nmethods'} value=2.4375 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Survivor Space} value=7 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=Metaspace} value=19.5 MiB
2021-05-03 22:31:16.211  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=2.4375 MiB
2021-05-03 22:31:16.212  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Eden Space} value=-1 B
2021-05-03 22:31:16.212  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'profiled nmethods'} value=117.214844 MiB
2021-05-03 22:31:16.212  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=Compressed Class Space} value=1 GiB
2021-05-03 22:31:16.212  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=117.21875 MiB
2021-05-03 22:31:16.212  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Old Gen} value=3.888672 GiB
2021-05-03 22:31:16.213  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'non-nmethods'} value=5.566406 MiB
2021-05-03 22:31:16.213  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=Metaspace} value=-1 B
2021-05-03 22:31:16.213  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Survivor Space} value=-1 B
2021-05-03 22:31:16.213  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=Compressed Class Space} value=2.376991 MiB
2021-05-03 22:31:16.213  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=Metaspace} value=18.34124 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=1.75354 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Eden Space} value=5 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Survivor Space} value=7 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'non-nmethods'} value=1.118042 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'profiled nmethods'} value=6.87854 MiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Old Gen} value=541.34375 KiB
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.daemon{} value=6 threads
2021-05-03 22:31:16.214  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.live{} value=7 threads
2021-05-03 22:31:16.215  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.peak{} value=7 threads
2021-05-03 22:31:16.216  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=blocked} value=0 threads
2021-05-03 22:31:16.216  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=runnable} value=3 threads
2021-05-03 22:31:16.216  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=waiting} value=2 threads
2021-05-03 22:31:16.217  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=new} value=0 threads
2021-05-03 22:31:16.217  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=timed-waiting} value=2 threads
2021-05-03 22:31:16.217  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=terminated} value=0 threads
2021-05-03 22:31:16.217  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : process.cpu.usage{} value=0
2021-05-03 22:31:16.218  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : process.files.max{} value=1048576 files
2021-05-03 22:31:16.218  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : process.files.open{} value=9 files
2021-05-03 22:31:16.218  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : process.start.time{} value=450013h 30m 14.272999936s
2021-05-03 22:31:16.218  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : process.uptime{} value=1m 1.985s
2021-05-03 22:31:16.218  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : system.cpu.count{} value=8
2021-05-03 22:31:16.219  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : system.cpu.usage{} value=0
2021-05-03 22:31:16.219  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : system.load.average.1m{} value=0.7
2021-05-03 22:31:16.221  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.pause{action=end of minor GC,cause=G1 Evacuation Pause} throughput=0.016667/s mean=0.013s max=0.013s

キャッシュの情報も含まれています。

2021-05-03 22:31:16.207  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=hit} throughput=0.016667/s
2021-05-03 22:31:16.207  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=miss} throughput=0.166667/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.memory.allocated{} throughput=2.45 MiB/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.memory.promoted{} throughput=9.022396 KiB/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : logback.events{level=info} throughput=0.433333 events/s
2021-05-03 22:31:16.208  INFO 43396 --- [trics-publisher] i.m.c.i.logging.LoggingMeterRegistry     : cache.size{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache} value=9

スレッド名が、不思議なものになっていますね。これは、デフォルトでlogging-metrics-publisherとなっています。

https://github.com/micrometer-metrics/micrometer/blob/v1.6.6/micrometer-core/src/main/java/io/micrometer/core/instrument/logging/LoggingMeterRegistry.java#L66

あと、アプリケーションの停止時にもShutdown Hookでメトリクスのログ出力が行われます。

2021-05-03 22:32:20.557  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : get message = Hello 15
2021-05-03 22:32:21.558  INFO 43396 --- [           main] org.littlewings.spring.metrics.App       : end
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=hit} throughput=0.066667/s
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=miss} throughput=0.166667/s
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : logback.events{level=info} throughput=1.316667 events/s
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : cache.size{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache} value=20
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.count{id=mapped} value=0 buffers
2021-05-03 22:32:21.564  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.count{id=direct} value=1 buffers
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.memory.used{id=direct} value=8 KiB
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.memory.used{id=mapped} value=0 B
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.total.capacity{id=direct} value=8 KiB
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.buffer.total.capacity{id=mapped} value=0 B
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.classes.loaded{} value=4825 classes
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.live.data.size{} value=0 B
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.gc.max.data.size{} value=3.888672 GiB
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Old Gen} value=94 MiB
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Eden Space} value=151 MiB
2021-05-03 22:32:21.565  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=Compressed Class Space} value=2.75 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'profiled nmethods'} value=7.0625 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'non-nmethods'} value=2.4375 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=heap,id=G1 Survivor Space} value=7 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=Metaspace} value=19.5 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.committed{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=2.4375 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Eden Space} value=-1 B
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'profiled nmethods'} value=117.214844 MiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=Compressed Class Space} value=1 GiB
2021-05-03 22:32:21.566  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=117.21875 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Old Gen} value=3.888672 GiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=CodeHeap 'non-nmethods'} value=5.566406 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=nonheap,id=Metaspace} value=-1 B
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.max{area=heap,id=G1 Survivor Space} value=-1 B
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=Compressed Class Space} value=2.387825 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=Metaspace} value=18.455597 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'non-profiled nmethods'} value=1.785645 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Eden Space} value=6 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Survivor Space} value=7 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'non-nmethods'} value=1.121338 MiB
2021-05-03 22:32:21.567  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=nonheap,id=CodeHeap 'profiled nmethods'} value=7.046753 MiB
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.memory.used{area=heap,id=G1 Old Gen} value=541.34375 KiB
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.daemon{} value=6 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.live{} value=8 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.peak{} value=9 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=blocked} value=0 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=runnable} value=3 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=waiting} value=3 threads
2021-05-03 22:32:21.568  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=new} value=0 threads
2021-05-03 22:32:21.569  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=timed-waiting} value=2 threads
2021-05-03 22:32:21.569  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : jvm.threads.states{state=terminated} value=0 threads
2021-05-03 22:32:21.569  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : process.cpu.usage{} value=0.000702
2021-05-03 22:32:21.569  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : process.files.max{} value=1048576 files
2021-05-03 22:32:21.569  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : process.files.open{} value=9 files
2021-05-03 22:32:21.570  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : process.start.time{} value=450013h 30m 14.272999936s
2021-05-03 22:32:21.570  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : process.uptime{} value=2m 7.336s
2021-05-03 22:32:21.570  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : system.cpu.count{} value=8
2021-05-03 22:32:21.570  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : system.cpu.usage{} value=0.079138
2021-05-03 22:32:21.571  INFO 43396 --- [extShutdownHook] i.m.c.i.logging.LoggingMeterRegistry     : system.load.average.1m{} value=1.13

これは、LoggingMeterRegistryの親クラスであるMeterRegistryにcloseメソッドが定義されているからですね。

MeterRegistry (micrometer-core 1.6.6 API)

LoggingMeterRegistryが使われるのは？

ところで、LoggingMeterRegistryをBean登録しただけで使われたのは？というと、このあたりの仕組みですね。

https://github.com/spring-projects/spring-boot/blob/v2.4.5/spring-boot-project/spring-boot-actuator-autoconfigure/src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/MeterRegistryPostProcessor.java#L63-L65

Bean登録した際に、MicrometerのMetricsに登録されるからです。

LoggingMeterRegistryの設定をしてみる

これで終わってもなんなので、LoggingMeterRegistryの設定をしてみましょう。

LoggingMeterRegistry.Builderを使うことで、ある程度設定可能です。

LoggingMeterRegistry.Builder (micrometer-core 1.6.6 API)

@Configuration
public class MetricsConfig {
    @Bean
    public MeterRegistry meterRegistry() {
        return LoggingMeterRegistry
                .builder(LoggingRegistryConfig.DEFAULT)
                .loggingSink(m -> System.out.println(m))
                .build();
    }
}

今回は、メトリクスの出力先を標準出力にしてみました。

結果はこちら。

cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=hit} throughput=0.016667/s
cache.gets{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache,result=miss} throughput=0.166667/s
logback.events{level=info} throughput=0.366667 events/s
cache.size{cache=caffeineCache,cacheManager=cacheManager,name=caffeineCache} value=9
jvm.buffer.count{id=mapped} value=0 buffers
jvm.buffer.count{id=direct} value=1 buffers
jvm.buffer.memory.used{id=direct} value=8 KiB
jvm.buffer.memory.used{id=mapped} value=0 B
jvm.buffer.total.capacity{id=direct} value=8 KiB
jvm.buffer.total.capacity{id=mapped} value=0 B

〜省略〜

標準出力に書き出すだけだと意味がありませんが、メトリクスの出力先をコントロールしたい場合に使うとよいでしょう。

ちなみに、SLF4Jを使う場合のデフォルトのロガー名は、io.micrometer.core.instrument.logging.LoggingMeterRegistry
となります（クラス名）。

もう1パターンやってみましょう。

LoggingMeterRegistry.Builderで設定できない項目を変えたい場合は、LoggingMeterRegistryの実装クラスを作成することに
なります。

@Configuration
public class MetricsConfig {
    @Bean
    public MeterRegistry meterRegistry() {
        return LoggingMeterRegistry
                .builder(new LoggingRegistryConfig() {
                    @Override
                    public Duration step() {
                        return Duration.ofSeconds(10L);
                    }

                    @Override
                    public String get(String key) {
                        return null;
                    }
                })
                .loggingSink(m -> System.out.println(m))
                .build();
    }
}

今回は、メトリクスを10秒おき（step）に出力するようにしてみました。

LoggingMeterRegistry#getがnullを返していますが、これはデフォルト実装と同じです。特に変えなくていいと思います…。

結果については、割愛。

まとめ

Spring Boot Actuatorで、Micrometerによるメトリクスをログ出力するようにしてみました。

ちょっとした確認などの際に、知っておくと便利なのではないでしょうか。

CLOVER🍀

That was when it all began.