CLOVER🍀

That was when it all began.

DomaのロガーをSLF4Jにする

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

DomaのログをSLF4Jに変更できるということを知らなかったので、1度確認しておこうかなと。

Doma SLF4Jサポート

doma-slf4jというものを使うとSlf4jJdbcLoggerが使えるようになり、UtilLoggingJdbcLoggerの代わりにJdbcLoggerとして
使うことでログ出力をj.u.l.LoggerからSLF4Jに切り替えることができます。

SLF4J support — Doma documentation

Doma 2.43.0(2020年9月末付近)から使える機能なんですね。

使い方自体は上記のとおりなので、今回はこちらを簡単に試してみようと思います。

なお、Slf4jJdbcLoggerが出力するログのデフォルトのログレベルはDEBUGです。

ドキュメントに書かれていますが、ロガーの名前はorg.seasar.doma.jdbc.LogKind.[ログ種の名前]となっています。

環境

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

$ 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"

データベースはMySQL 8.0.24を使い、172.17.0.2でアクセスできるものとします。

準備

Maven依存関係は、このようにしました。

    <dependencies>
        <dependency>
            <groupId>org.seasar.doma</groupId>
            <artifactId>doma-core</artifactId>
            <version>2.46.1</version>
        </dependency>
        <dependency>
            <groupId>org.seasar.doma</groupId>
            <artifactId>doma-slf4j</artifactId>
            <version>2.46.1</version>
        </dependency>
        <dependency>
            <groupId>org.seasar.doma</groupId>
            <artifactId>doma-processor</artifactId>
            <version>2.46.1</version>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-simple</artifactId>
            <version>1.7.30</version>
        </dependency>
        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
            <version>8.0.24</version>
        </dependency>
    </dependencies>

MySQL Connector/Jのスコープがruntimeになっていないのは、AbandonedConnectionCleanupThreadを使ったからです…。
ソースコードに出てきます

SLF4Jが利用するログ実装は、slf4j-simpleとしました。

ソースコードを作成する

では、ソースコードを作成していきます。

Configクラス。

src/main/java/org/littlewings/doma/DomaConfig.java

package org.littlewings.doma;

import javax.sql.DataSource;

import org.seasar.doma.jdbc.Config;
import org.seasar.doma.jdbc.JdbcLogger;
import org.seasar.doma.jdbc.Naming;
import org.seasar.doma.jdbc.Slf4jJdbcLogger;
import org.seasar.doma.jdbc.dialect.Dialect;
import org.seasar.doma.jdbc.dialect.MysqlDialect;
import org.seasar.doma.jdbc.tx.LocalTransactionDataSource;
import org.seasar.doma.jdbc.tx.LocalTransactionManager;
import org.seasar.doma.jdbc.tx.TransactionManager;
import org.slf4j.event.Level;

public class DomaConfig implements Config {
    static final DomaConfig CONFIG = new DomaConfig();

    Dialect dialect = new MysqlDialect();
    JdbcLogger jdbcLogger = new Slf4jJdbcLogger();
    LocalTransactionDataSource dataSource =
            new LocalTransactionDataSource(
                    "jdbc:mysql://172.17.0.2:3306/practice?characterEncoding=utf-8&characterSetResults=utf-8",
                    "kazuhira",
                    "password"
            );
    TransactionManager transactionManager = new LocalTransactionManager(dataSource, jdbcLogger);

    public static DomaConfig singleton() {
        return CONFIG;
    }

    @Override
    public DataSource getDataSource() {
        return dataSource;
    }

    @Override
    public Dialect getDialect() {
        return dialect;
    }

    @Override
    public JdbcLogger getJdbcLogger() {
        return jdbcLogger;
    }

    @Override
    public TransactionManager getTransactionManager() {
        return transactionManager;
    }

    @Override
    public Naming getNaming() {
        return Naming.SNAKE_LOWER_CASE;
    }
}

DataSource等いろいろ書いていますが、ポイントはSlf4jJdbcLoggerを使って

    JdbcLogger jdbcLogger = new Slf4jJdbcLogger();

getJdbcLoggerメソッドの戻り値とすることだけですね。

    @Override
    public JdbcLogger getJdbcLogger() {
        return jdbcLogger;
    }

エンティティクラス。

src/main/java/org/littlewings/doma/Book.java

package org.littlewings.doma;

import org.seasar.doma.Entity;
import org.seasar.doma.Id;

@Entity
public class Book {
    @Id
    String isbn;

    String title;

    Integer price;

    public static Book create(String isbn, String title, Integer price) {
        Book book = new Book();

        book.setIsbn(isbn);
        book.setTitle(title);
        book.setPrice(price);

        return book;
    }

    // getter/setterは省略
}

Daoインターフェース。

src/main/java/org/littlewings/doma/BookDao.java

package org.littlewings.doma;

import java.util.stream.Stream;

import org.seasar.doma.Dao;
import org.seasar.doma.Insert;
import org.seasar.doma.Script;
import org.seasar.doma.Select;
import org.seasar.doma.Sql;

@Dao
public interface BookDao {
    @Sql("drop table if exists book; create table book(isbn varchar(14), title varchar(100), price int, primary key(isbn))")
    @Script
    void createTable();

    @Insert
    int insert(Book book);

    @Sql("select * from book where isbn = /* isbn */'dummy'")
    @Select
    Book selectByIsbn(String isbn);

    @Sql("select * from book order by price desc")
    @Select
    Stream<Book> selectAllOrderByPrice();
}

メインクラス。

src/main/java/org/littlewings/doma/App.java

package org.littlewings.doma;

import com.mysql.cj.jdbc.AbandonedConnectionCleanupThread;
import org.seasar.doma.jdbc.tx.TransactionManager;

public class App {
    public static void main(String... args) {
        System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "DEBUG");

        DomaConfig config = DomaConfig.singleton();
        TransactionManager tm = config.getTransactionManager();
        BookDao dao = new BookDaoImpl(config);

        tm.required(() -> {
            dao.createTable();

            dao.insert(Book.create("978-4798161488", "MySQL徹底入門 第4版 MySQL 8.0対応", 4180));
            dao.insert(Book.create("978-4873116389", "実践ハイパフォーマンスMySQL 第3版", 5280));
            dao.insert(Book.create("978-4798147406", "詳解MySQL 5.7 止まらぬ進化に乗り遅れないためのテクニカルガイド", 3960));
        });

        tm.required(() -> {
            Book book = dao.selectByIsbn("978-4798161488");
            System.out.printf("simple: %s / %s / %d%n", book.getIsbn(), book.getTitle(), book.getPrice());

            dao.selectAllOrderByPrice().forEach(b -> System.out.printf("foreach: %s / %s / %d%n", b.getIsbn(), b.getTitle(), b.getPrice()));
        });

        AbandonedConnectionCleanupThread.checkedShutdown();
    }
}

使い方自体には特に注意点はないのですが、先述のとおりSlf4jJdbcLoggerが出力時のログレベルはDEBUGなので、
slf4j-simpleのデフォルトログレベルもDEBUGにしておきました。

        System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "DEBUG");

確認

プログラムができたので、実行します。

$ mvn compile exec:java -Dexec.mainClass=org.littlewings.doma.App

すると、こんな感じのログが得られます。

[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2063] The local transaction "165839599" is begun.
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=createTable
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.SCRIPT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#createTable],
drop table if exists book
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.SCRIPT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#createTable],
create table book(isbn varchar(14), title varchar(100), price int, primary key(isbn))
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=createTable
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4798161488', 'MySQL徹底入門 第4版 MySQL 8.0対応', 4180)
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4873116389', '実践ハイパフォーマンスMySQL 第3版', 5280)
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4798147406', '詳解MySQL 5.7 止まらぬ進化に乗り遅れないためのテクニカルガイド', 3960)
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2067] The local transaction "165839599" is committed.
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2064] The local transaction "165839599" is ended.
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2063] The local transaction "151768958" is begun.
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectByIsbn
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.SELECT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#selectByIsbn],
select * from book where isbn = '978-4798161488'
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectByIsbn
simple: 978-4798161488 / MySQL徹底入門 第4版 MySQL 8.0対応 / 4180
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectAllOrderByPrice
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.SQL.SELECT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#selectAllOrderByPrice],
select * from book order by price desc
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectAllOrderByPrice
foreach: 978-4873116389 / 実践ハイパフォーマンスMySQL 第3版 / 5280
foreach: 978-4798161488 / MySQL徹底入門 第4版 MySQL 8.0対応 / 4180
foreach: 978-4798147406 / 詳解MySQL 5.7 止まらぬ進化に乗り遅れないためのテクニカルガイド / 3960
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2067] The local transaction "151768958" is committed.
[org.littlewings.doma.App.main()] DEBUG org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2064] The local transaction "151768958" is ended.

OKですね。

デフォルトのログレベルの定義は?

ところでデフォルトのログレベルがDEBUGということで、どこで決まっているのかな?と思ったのですが、こちらのようです。

https://github.com/domaframework/doma/blob/2.46.1/doma-slf4j/src/main/java/org/seasar/doma/jdbc/Slf4jJdbcLogger.java#L15

ログレベルは、コンストラクタで指定できそうですね。

試しに、ログレベルをINFOにしてみましょう。こちらのslf4j-simpleの設定はコメントアウトして
※この時点で、そのままだとログが出なくなります

        // System.setProperty("org.slf4j.simpleLogger.defaultLogLevel", "DEBUG");

Configクラスで指定しているSlf4jJdbcLoggerのコンストラクタにログレベルを指定。

    JdbcLogger jdbcLogger = new Slf4jJdbcLogger(Level.INFO);

すると、ログレベルが変更できました、と。

[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2063] The local transaction "2050876570" is begun.
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=createTable
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.SCRIPT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#createTable],
drop table if exists book
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.SCRIPT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#createTable],
create table book(isbn varchar(14), title varchar(100), price int, primary key(isbn))
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=createTable
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4798161488', 'MySQL徹底入門 第4版 MySQL 8.0対応', 4180)
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4873116389', '実践ハイパフォーマンスMySQL 第3版', 5280)
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.INSERT - [DOMA2076] SQL LOG : PATH=[null],
insert into book (isbn, title, price) values ('978-4798147406', '詳解MySQL 5.7 止まらぬ進化に乗り遅れないためのテクニカルガイド', 3960)
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=insert
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2067] The local transaction "2050876570" is committed.
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2064] The local transaction "2050876570" is ended.
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2063] The local transaction "896707861" is begun.
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectByIsbn
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.SELECT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#selectByIsbn],
select * from book where isbn = '978-4798161488'
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectByIsbn
simple: 978-4798161488 / MySQL徹底入門 第4版 MySQL 8.0対応 / 4180
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2220] ENTER  : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectAllOrderByPrice
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.SQL.SELECT - [DOMA2076] SQL LOG : PATH=[org.littlewings.doma.BookDao#selectAllOrderByPrice],
select * from book order by price desc
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.DAO - [DOMA2221] EXIT   : CLASS=org.littlewings.doma.BookDaoImpl, METHOD=selectAllOrderByPrice
foreach: 978-4873116389 / 実践ハイパフォーマンスMySQL 第3版 / 5280
foreach: 978-4798161488 / MySQL徹底入門 第4版 MySQL 8.0対応 / 4180
foreach: 978-4798147406 / 詳解MySQL 5.7 止まらぬ進化に乗り遅れないためのテクニカルガイド / 3960
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2067] The local transaction "896707861" is committed.
[org.littlewings.doma.App.main()] INFO org.seasar.doma.jdbc.LogKind.LOCAL_TRANSACTION - [DOMA2064] The local transaction "896707861" is ended.

とはいえ、ふだんはDEBUGレベルのままで良いでしょうね。

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を使用します。

プロジェクトの作成

依存関係にactuatorcacheを加えて、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の親クラスであるMeterRegistrycloseメソッドが定義されているからですね。

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

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/MeterRegistryConfigurer.java#L71

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#getnullを返していますが、これはデフォルト実装と同じです。特に変えなくていいと思います…。

結果については、割愛。

まとめ

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

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