目录
1、只开启请求的 SQL 和具体参数：
2、记录完整的 SQL 和执行时长：
3、记录返回的结果集 或 更新行数等日志
同样为了问题排查，需要开启数据库的访问日志，了解请求的 SQL 及具体参数，最好还记录一下时长，以便排查慢查询，最好还能有返回结果情况，下面简介一下如何开启 JPA 的日志：
注：本文基于
spring-boot-starter-parent 2.3.4.RELEASE
1、只开启请求的 SQL 和具体参数：
如果有 sql 和参数就够了，那么在 application.yml 里添加如下配置就好了：
logging:
level:
org.hibernate.SQL: debug
org.hibernate.type.descriptor.sql.BasicBinder: trace
启动项目输出日志如下：
2020-10-14 20:11:41.992 DEBUG 27780 — [nio-8080-exec-4] org.hibernate.SQL : select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_, aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=?
2020-10-14 20:11:41.992 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] – [4]
2020-10-14 20:11:42.005 DEBUG 27780 — [nio-8080-exec-4] org.hibernate.SQL : select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_, aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=?
2020-10-14 20:11:42.005 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] – [4]
2020-10-14 20:11:42.018 DEBUG 27780 — [nio-8080-exec-4] org.hibernate.SQL : update Aaa set dishId=?, dishhour=?, num=?, restId=? where id=?
2020-10-14 20:11:42.018 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [BIGINT] – [343]
2020-10-14 20:11:42.019 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [INTEGER] – [46]
2020-10-14 20:11:42.019 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [3] as [INTEGER] – [333]
2020-10-14 20:11:42.019 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [4] as [BIGINT] – [522]
2020-10-14 20:11:42.019 TRACE 27780 — [nio-8080-exec-4] o.h.type.descriptor.sql.BasicBinder : binding parameter [5] as [BIGINT] – [4]
2、记录完整的 SQL 和执行时长：
这个就需要使用一些插件了，比如
2.1、log4jdbc
源码：https://github.com/arthurblake/log4jdbc
这货已经无数年未更新了，而且用的是旧的 mysql 驱动，会告警，但是不影响：
Loading class `com.mysql.jdbc.Driver’. This is deprecated. The new driver class is `com.mysql.cj.jdbc.Driver’. The driver is automatically registered via the SPI and manual loading of the driver class is generally unnecessary.
使用前要先引入：
<dependency>
<groupId>com.googlecode.log4jdbc</groupId>
<artifactId>log4jdbc</artifactId>
<version>1.2</version>
</dependency>
接着修改 application.yml
spring:
datasource: # url 和 driver-class-name 都要改成 log4jdbc 格式
url: jdbc:log4jdbc:mysql://10.1.2.3:3306/db?characterEncoding=utf8&serverTimezone=Asia/Shanghai&useSSL=false
driver-class-name: net.sf.log4jdbc.DriverSpy # com.mysql.cj.jdbc.Driver
username: user
password: 123
logging:
level: # 关闭不需要的 4 种 log4jdbc日志
jdbc.connection: off
jdbc.resultset: off
jdbc.audit: off
jdbc.sqlonly: off
2020-10-15 09:10:37.300 INFO 28536 — [nio-8080-exec-4] jdbc.sqltiming : select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_,
aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=4
{executed in 1 msec}
2020-10-15 09:10:37.309 INFO 28536 — [nio-8080-exec-4] jdbc.sqltiming : select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_,
aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=4
{executed in 1 msec}
2020-10-15 09:10:37.321 INFO 28536 — [nio-8080-exec-4] jdbc.sqltiming : update Aaa set dishId=343, dishhour=48, num=333, restId=522 where id=4
{executed in 1 msec}
2.2、p6spy
源码： https://github.com/p6spy/p6spy
这个现在还在更新中，使用上比较复杂一些，而且还需要独立的配置文件，
我写了一个使用 Demo 在：
https://github.com/youbl/study/tree/master/p6spy-dblogdemo
可以不需要独立配置文件，而是合并到 application.yml 里，
这个组件也需要修改 yml 里的 url 和 driver-class-name
P6SPY 输出的日志格式参考：
2020-10-14 20:34:05.982 INFO 32752 — [nio-8080-exec-1] p6spy : 连接:0|时长:3|sql:[statement]select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_, aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=4
2020-10-14 20:34:05.995 INFO 32752 — [nio-8080-exec-1] p6spy : 连接:0|时长:0|sql:[commit]
2020-10-14 20:34:06.049 INFO 32752 — [nio-8080-exec-1] p6spy : 连接:0|时长:1|sql:[statement]select aaa0_.id as id1_0_0_, aaa0_.dishId as dishid2_0_0_, aaa0_.dishhour as dishhour3_0_0_, aaa0_.num as num4_0_0_, aaa0_.restId as restid5_0_0_ from Aaa aaa0_ where aaa0_.id=4
2020-10-14 20:34:06.068 INFO 32752 — [nio-8080-exec-1] p6spy : 连接:0|时长:7|sql:[statement]update Aaa set dishId=343, dishhour=47, num=333, restId=522 where id=4
2020-10-14 20:34:06.072 INFO 32752 — [nio-8080-exec-1] p6spy : 连接:0|时长:1|sql:[commit]
3、记录返回的结果集 或 更新行数等日志
P6SPY 组件支持自定义 JdbcEventListener，可以得到更新行数，参考 DEMO：
https://github.com/youbl/study/tree/master/p6spy-dblogdemo
但 P6SPY 不支持输出结果集，因此我用 Aspect 切面去拦截参数和返回结果，
3.1、先开启 SQL 日志：
logging:
level:
org.hibernate.SQL: debug
org.hibernate.type.descriptor.sql.BasicBinder: info # 不用它的参数记录
3.2、AOP 切面代码参考如下：
注：只输出了结果行数，没输出结果，避免结果集太大，你可以自己改代码输出结果
package com.mike.boot.web.log;
import com.fasterxml.jackson.annotation.JsonIgnore;
import com.fasterxml.jackson.annotation.JsonInclude;
import com.fasterxml.jackson.databind.ObjectMapper;
import lombok.Data;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;import java.lang.reflect.Method;
import java.util.Collection;/**
* 用于JPA的日志服务类
*/
@Aspect
@Slf4j
public class JpaAop {
private static ObjectMapper mapper = new ObjectMapper().setSerializationInclusion(JsonInclude.Include.NON_NULL);@Pointcut(“execution(* org.springframework.data.jpa.repository.JpaRepository.*(..))”)
//@Pointcut(“@within(org.springframework.data.repository.NoRepositoryBean)”)
public void getPointcut() {
// do nothing because @Pointcut
}@Around(“getPointcut()”)
public Object around1(ProceedingJoinPoint joinPoint) throws Throwable {
if (!log.isDebugEnabled()) {
return joinPoint.proceed();
}
return logAround(joinPoint);
}@Pointcut(“@annotation(org.springframework.data.jpa.repository.Query)”)
public void getPointcutQuery() {
// do nothing because @Pointcut
}@Around(“getPointcutQuery()”)
public Object around2(ProceedingJoinPoint joinPoint) throws Throwable {
if (!log.isDebugEnabled()) {
return joinPoint.proceed();
}
return logAround(joinPoint);
}protected void doLog(Dto dto) {
// 不直接记录结果集，避免太大
if (dto.getResult() != null && dto.getResult() instanceof Collection) {
dto.setResult(“结果行数:” + ((Collection) dto.getResult()).size());
}
if (dto.getExp() != null) {
log.warn(serial(dto));
} else {
log.info(serial(dto));
}
}public Object logAround(ProceedingJoinPoint point) throws Throwable {
long beginTime = System.currentTimeMillis();
Object result = null;
Exception exception = null;
try {
result = point.proceed();
} catch (Exception exp) {
exception = exp;
}
long time = System.currentTimeMillis() – beginTime;
saveLog(point, result, exception, time);if (exception != null) {
throw exception;
}
return result;
}private void saveLog(ProceedingJoinPoint joinPoint, Object result, Exception exception, long time) {
Dto dto = new Dto();
dto.setCostTime(time);try {
if (exception != null) {
dto.setExp(exception);
}MethodSignature signature = (MethodSignature) joinPoint.getSignature();
Method method = signature.getMethod();
NeedLog annotation = method.getAnnotation(NeedLog.class);
if (annotation != null) {
dto.setAnnnotation(annotation);//注解上的描述
dto.setRemark(annotation.value());if (annotation.logReturn() && result != null) {
dto.setResult(result);
}
} else if (result != null) {
dto.setResult(result);
}//请求的 类名、方法名
String className = joinPoint.getTarget().getClass().getName();
String signName = signature.getDeclaringTypeName();
if (!signName.equalsIgnoreCase(className))
signName += “|” + className;
dto.setClas(signName);String methodName = signature.getName();
dto.setMethod(methodName);//请求的参数
Object[] args = joinPoint.getArgs();
if (args != null && args.length > 0) {
dto.setPara(serial(args));
}} catch (Exception e) {
dto.setExp(e);
}doLog(dto);
}protected static String serial(Object obj) {
try {
return mapper.writeValueAsString(obj);
} catch (Exception ex) {
return obj.toString();
}
}@Data
protected static class Dto {
/**
* 调用类名
*/
private String clas;
/**
* 调用方法名
*/
private String method;
/**
* 调用的参数
*/
private String para;
/**
* 方法返回结果
*/
private Object result;
/**
* 执行时长，毫秒
*/
private long costTime;
/**
* 备注
*/
private String remark;/**
* 出现的异常
*/
private Exception exp;@JsonIgnore
private NeedLog annnotation;
}
}
3.3、输出日志参考如下：
2020-10-14 20:43:41 DEBUG 32764 — [nio-8080-exec-1] org.hibernate.SQL : select aaa0_.id as id1_0_0_, aaa0_.dish_hour as dish_hou2_0_0_, aaa0_.dish_id as dish_id3_0_0_, aaa0_.num as num4_0_0_, aaa0_.rest_id as rest_id5_0_0_ from aaa aaa0_ where aaa0_.id=?
2020-10-14 20:43:41 INFO 32764 — [nio-8080-exec-1] com.mike.boot.web.log.JpaAop : {“clas”:”org.springframework.data.repository.CrudRepository|com.sun.proxy.$Proxy204″,”method”:”findById”,”para”:”[4]”,”result”:{“present”:false},”costTime”:76}
2020-10-14 20:43:41 DEBUG 32764 — [nio-8080-exec-1] org.hibernate.SQL : insert into aaa (id, dish_hour, dish_id, num, rest_id) values (null, ?, ?, ?, ?)
2020-10-14 20:43:41 INFO 32764 — [nio-8080-exec-1] com.mike.boot.web.log.JpaAop : {“clas”:”org.springframework.data.repository.CrudRepository|com.sun.proxy.$Proxy204″,”method”:”save”,”para”:”[{\”id\”:1,\”restId\”:0,\”dishHour\”:1,\”dishId\”:0,\”num\”:0}]”,”result”:{“id”:1,”restId”:0,”dishHour”:1,”dishId”:0,”num”:0},”costTime”:60}
