今回は、SQLログ出力内容をカスタマイズし、SQLの実行時間や呼出メソッドをSQLログに出力してみたので、そのサンプルプログラムを共有する。
前提条件
下記記事の実装が完了していること。

サンプルプログラムの内容
今回のサンプルプログラムの構成は以下の通り。
なお、上記赤枠が前提条件のプログラムと変更になった箇所で「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) 検索し一覧を表示する場合の、画面とログ出力内容は以下の通り。
<画面>

2) データ更新を行う場合の、画面とログ出力内容は以下の通り。
<画面>



3) データ削除を行う場合の、画面とログ出力内容は以下の通り。
<画面>


4) データ追加を行う場合の、画面とログ出力内容は以下の通り。
<画面>



要点まとめ
- SQL実行時間をログ出力するようにするには、MyBatisのログ出力内容をカスタマイズすればよい。