• 欢迎访问露水湾网站,WordPress信息,WordPress教程,推荐使用最新版火狐浏览器和Chrome浏览器访问本网站
  • Git主题现已支持滚动公告栏功能,兼容其他浏览器,看到的就是咯,在后台最新消息那里用li标签添加即可。
  • 最新版Git主题已支持说说碎语功能,可像添加文章一样直接添加说说,新建说说页面即可,最后重新保存固定连接,

全局记录JPA的SQL、参数和执行时长日志

大数据库 dewbay 5个月前 (06-08) 281次浏览 已收录 0个评论 扫描二维码

目录
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

OK,输出日志格式参考,有完整的 sql 和执行时长

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}


露水湾 , 版权所有丨如未注明 , 均为原创丨本网站采用BY-NC-SA协议进行授权
转载请注明原文链接:全局记录JPA的SQL、参数和执行时长日志
喜欢 (0)
[]
分享 (0)
关于作者:
发表我的评论
取消评论

表情 贴图 加粗 删除线 居中 斜体 签到

Hi,您需要填写昵称和邮箱!

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址