Spring Boot ログ出力

SQLログ出力内容をカスタマイズしてみた

 

今回は、SQLログ出力内容をカスタマイズし、SQLの実行時間や呼出メソッドをSQLログに出力してみたので、そのサンプルプログラムを共有する。

前提条件

下記記事の実装が完了していること。

log4j2のファイルにymlを利用してみた前回は、log4j2のファイルにxmlファイルを利用していたが、今回はlog4j2のファイルにymlを利用してみたので、そのサンプルプロ...

サンプルプログラムの内容

今回のサンプルプログラムの構成は以下の通り。
サンプルプログラムの構成
なお、上記赤枠が前提条件のプログラムと変更になった箇所で「DemoSqlInvocation.java」が新規で作成したプログラムで、「build.gradle」「log4j2.yml」は変更したプログラムとなる。
また、上図には無いが、前提条件のプログラムに入っていた「mybatis-config.xml」は不要なので、今回削除している。

build.gradleの内容は以下の通りで、「Apache Common JEXL」を利用するための設定を追加している。なお、「Apache Common JEXL」は、SQLの埋め込みパラメータ値を取得するために利用している。

plugins {
	id 'org.springframework.boot' version '2.1.7.RELEASE'
	id 'java'
}

apply plugin: 'io.spring.dependency-management'

group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '1.8'

repositories {
	mavenCentral()
}

configurations {
	//log4j2を利用するため、Spring BootデフォルトのLogbackを利用しないよう設定
	all*.exclude module : 'spring-boot-starter-logging'
}

dependencies {
	implementation 'org.springframework.boot:spring-boot-starter-thymeleaf'
	implementation 'org.springframework.boot:spring-boot-starter-web'
	testImplementation 'org.springframework.boot:spring-boot-starter-test'
	compileOnly 'org.projectlombok:lombok:1.18.10'
	annotationProcessor 'org.projectlombok:lombok:1.18.10'
	compile files('lib/ojdbc6.jar')
	implementation 'org.mybatis.spring.boot:mybatis-spring-boot-starter:2.1.1'
	compile group: 'org.springframework.data', name: 'spring-data-commons-core', version: '1.1.0.RELEASE'
	//log4j2を利用するための設定
	compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.12.1'
	compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.12.1'
	//AOPを利用するための設定
	implementation 'org.springframework.boot:spring-boot-starter-aop'
	//log4j2の設定でymlファイルを利用するための設定
	compile group: 'com.fasterxml.jackson.dataformat', name: 'jackson-dataformat-yaml', version: '2.10.1'
	compile group: 'com.fasterxml.jackson.core', name: 'jackson-core', version: '2.10.1'
	compile group: 'com.fasterxml.jackson.core', name: 'jackson-databind', version: '2.10.1'
	//Apache Common JEXLを利用するための設定
	compile group: 'org.apache.commons', name: 'commons-jexl3', version: '3.0'
}

また、application.ymlの内容は以下の通りで、log4j2でSQLログを出力するための「mybatis-config.xml」を読み込む設定を削除している。

server:
  port: 8084
# DB接続情報
spring:
  datasource:
    url: jdbc:oracle:thin:@localhost:1521:xe
    username: USER01
    password: USER01
    driverClassName: oracle.jdbc.driver.OracleDriver
# 一覧画面で1ページに表示する行数
demo:
  list:
    pageSize: 2



また、DemoSqlInvocation.javaの内容は以下の通りで、SQLの実行時間・呼出メソッド・SQLログを出力するようにしている。

package com.example.demo;

import org.apache.commons.jexl3.JexlEngine;
import org.apache.commons.jexl3.JexlBuilder;
import org.apache.commons.jexl3.JexlException;

import org.apache.ibatis.executor.Executor;
import org.apache.ibatis.mapping.BoundSql;
import org.apache.ibatis.mapping.MappedStatement;
import org.apache.ibatis.mapping.ParameterMapping;

import org.apache.ibatis.plugin.Intercepts;
import org.apache.ibatis.plugin.Signature;
import org.apache.ibatis.plugin.Interceptor;
import org.apache.ibatis.plugin.Invocation;
import org.apache.ibatis.plugin.Plugin;

import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.session.RowBounds;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

import org.springframework.stereotype.Component;
import java.util.List;
import java.util.Properties;

//select, update, insert, deleteの各SQLを実行するタイミングで、
//このクラスのinterceptメソッドが呼ばれるように、
//@Intercepts・@Signatureのアノテーションを下記のように設定
@Intercepts({
        @Signature(type = Executor.class
                , method = "update"
                , args = {MappedStatement.class, Object.class}),
        @Signature(type = Executor.class
                , method = "query"
                , args = {MappedStatement.class, Object.class
                        , RowBounds.class, ResultHandler.class})
})
@Component
public class DemoSqlInvocation implements Interceptor {

    //ログ出力のためのクラス
    private Logger logger = LogManager.getLogger(DemoSqlInvocation.class);

    //SQLにマッピングされるパラメータ名に対応するパラメータ値を取得するために
    //JexlEngineオブジェクトを利用
    private JexlEngine engine = new JexlBuilder().create();

    /**
     * SQL実行前後に処理を追加する
     *
     * @param invocation　メソッド呼出用オブジェクト
     * @return SQL実行メソッドの戻り値
     * @throws Throwable
     */
    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        //返却オブジェクトを定義
        Object returnObj = null;

        //SQL実行メソッドを実行し、その開始・終了時刻も取得
        long start = System.currentTimeMillis();
        returnObj = invocation.proceed();
        long end = System.currentTimeMillis();

        //SQL実行時間、実行メソッド名(フルパス)を出力
        MappedStatement statement = (MappedStatement)invocation.getArgs()[0];
        String[] items = statement.getId().split("\\.");
        logger.info("実行時間: {} ms. 実行メソッド: {}"
                , end-start, String.join(".", items));

        //SQLログを出力
        Object parameter = invocation.getArgs()[1];
        BoundSql boundSql = statement.getBoundSql(parameter);
        logger.info("Preparing: {}", shapingSql(boundSql.getSql()));
        logger.info("Parameters: {}", getParameterValues(boundSql));

        return returnObj;
    }

    @Override
    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }

    @Override
    public void setProperties(Properties properties) {

    }

    /**
     * 引数のSQL文から、改行コード(LF)と連続する空白文字を除く
     * @param beforeSql SQL文
     * @return 整形後のSQL文
     */
    private String shapingSql(String beforeSql){
        if(DateCheckUtil.isEmpty(beforeSql)){
            return beforeSql;
        }
        return beforeSql.replaceAll("\n", "")
                .replaceAll(" {2,}", " ");
    }

    /**
     * 引数のBoundSqlから、SQLに埋め込まれるパラメータ値を取得する
     * @param boundSql BoundSqlオブジェクト
     * @return SQLに埋め込まれるパラメータ値
     */
    private String getParameterValues(final BoundSql boundSql) {
        //返却用戻り値を格納
        StringBuilder builder = new StringBuilder();
        //パラメータ値を取得
        Object param = boundSql.getParameterObject();
        if(param == null){
            //パラメータの設定が無い場合は、(No Params.)を返却
            builder.append("(No Params.)");
            return builder.toString();
        }
        //SQLにマッピングされるパラメータ名を取得
        List<ParameterMapping> paramMapping = boundSql.getParameterMappings();
        //SQLにマッピングされるパラメータ名に対応するパラメータ値を取得し、
        //返却用戻り値に順次格納する
        for (ParameterMapping mapping : paramMapping) {
            String propValue = mapping.getProperty();
            builder.append(propValue + "=");
            try {
                //SQLにマッピングされるパラメータ名に対応するパラメータ値を取得
                builder.append(engine.getProperty(param, propValue));
                builder.append(", ");
            } catch (JexlException e) {
                //パラメータ値がLong型の場合等はJexlExceptionが発生するため
                //パラメータ値をそのまま指定する
                builder.append(param);
                builder.append(", ");
                continue;
            }
        }
        //返却用戻り値の最後のカンマを除く
        if(builder.lastIndexOf(", ") > 0){
            builder.deleteCharAt(builder.lastIndexOf(", "));
        }
        return builder.toString();
    }

}

その他のソースコード内容は、以下のサイトを参照のこと。
https://github.com/purin-it/java/tree/master/spring-boot-custom-sqllog/demo



サンプルプログラムの実行結果

1) 検索し一覧を表示する場合の、画面とログ出力内容は以下の通り。
＜画面＞
実行結果_画面_検索_1

実行結果_画面_検索_2

＜ログ＞
実行結果_検索_ログ

2) データ更新を行う場合の、画面とログ出力内容は以下の通り。
＜画面＞
実行結果_画面_更新_1

実行結果_画面_更新_2 実行結果_画面_更新_3 実行結果_画面_更新_4

＜ログ＞
実行結果_更新_ログ

3) データ削除を行う場合の、画面とログ出力内容は以下の通り。
＜画面＞
実行結果_画面_削除_1

実行結果_画面_削除_2 実行結果_画面_削除_3

＜ログ＞
実行結果_ログ_削除

4) データ追加を行う場合の、画面とログ出力内容は以下の通り。
＜画面＞
実行結果_画面_追加_1

実行結果_画面_追加_2 実行結果_画面_追加_3 実行結果_画面_追加_4

＜ログ＞
実行結果_追加_ログ

要点まとめ

  • SQL実行時間をログ出力するようにするには、MyBatisのログ出力内容をカスタマイズすればよい。
RELATED POST