说明
用到的软件是
1.spring
2.hibernate
背景
为什么要做这个需求？
1.生产故障
间隔性出现提交事务耗时几分钟的情况，为什么确定是提交事务耗时几分钟，而不是其他原因？因为整个事务方法开始、执行sql1/sql2、方法结束，都是正常的，但是一出事务方法，就过了好几分钟。但是又无法证明这一点，暂时只是通过日志观察发现提交事务确实耗时了几分钟，所以要监控起来，到时候生产告警的时候，如果同时出现提交事务耗时几分钟的告警，那么就可以证明确实是提交事务耗时这么久。
2.提交事务的时候释放资源也可能耗时很久
获取资源和释放资源都可能耗时很久，获取数据库连接可能会耗时很久，释放数据库连接也可能要耗时很久。既然可能耗时很久，就需要监控起来。之前我们已经做了获取连接耗时监控。
提交事务-方法调用栈
1.提交事务方法调用栈
待补充
2.提交事务之后，释放资源方法调用栈
returnObject:1393, GenericObjectPool (org.apache.commons.pool.impl) //不是真的关闭，而是归还连接到连接池
close:90, PoolableConnection (org.apache.commons.dbcp)
close:191, PoolingDataSource$PoolGuardConnectionWrapper (org.apache.commons.dbcp) //关闭连接
doCloseConnection:341, DataSourceUtils (org.springframework.jdbc.datasource) //关闭连接
closeConnection:97, LocalDataSourceConnectionProvider (org.springframework.orm.hibernate3)
closeConnection:474, ConnectionManager (org.hibernate.jdbc) //关闭连接
cleanup:408, ConnectionManager (org.hibernate.jdbc)
close:347, ConnectionManager (org.hibernate.jdbc) //关闭连接
close:343, SessionImpl (org.hibernate.impl)
closeSession:802, SessionFactoryUtils (org.springframework.orm.hibernate3)
closeSessionOrRegisterDeferredClose:788, SessionFactoryUtils (org.springframework.orm.hibernate3) //关闭会话
doCleanupAfterCompletion:738, HibernateTransactionManager (org.springframework.orm.hibernate3) //hibernate事务管理器
cleanupAfterCompletion:1009, AbstractPlatformTransactionManager (org.springframework.transaction.support) //释放资源
processCommit:805, AbstractPlatformTransactionManager (org.springframework.transaction.support)
commit:724, AbstractPlatformTransactionManager (org.springframework.transaction.support)
commitTransactionAfterReturning:475, TransactionAspectSupport (org.springframework.transaction.interceptor) //提交事务
invokeWithinTransaction:270, TransactionAspectSupport (org.springframework.transaction.interceptor) //事务拦截器
invoke:94, TransactionInterceptor (org.springframework.transaction.interceptor) //事务拦截器
proceed:172, ReflectiveMethodInvocation (org.springframework.aop.framework)
invoke:91, ExposeInvocationInterceptor (org.springframework.aop.interceptor)
proceed:172, ReflectiveMethodInvocation (org.springframework.aop.framework)
intercept:631, CglibAopProxy$DynamicAdvisedInterceptor (org.springframework.aop.framework)
merModifyNoAudit:-1, UrmtminfService$$EnhancerByCGLIB$$57be0f77 (xxx.qrcode.register.dbservice.impl)
merModifyNoAudit:517, QrcodeRegisterServer (xxx.qrcode.register.remoteserver.impl)
invokeMethod:-1, Wrapper20 (com.alibaba.dubbo.common.bytecode)
doInvoke:47, JavassistProxyFactory$1 (com.alibaba.dubbo.rpc.proxy.javassist)
invoke:76, AbstractProxyInvoker (com.alibaba.dubbo.rpc.proxy)
invoke:52, DelegateProviderMetaDataInvoker (com.alibaba.dubbo.config.invoker)
invoke:56, InvokerWrapper (com.alibaba.dubbo.rpc.protocol)
invoke:11, AppNameAppendFilter (com.xxx.log.rpc.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:62, ExceptionFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:42, TimeoutFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:60, ExecuteLimitFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:75, MonitorFilter (com.alibaba.dubbo.monitor.support)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:78, TraceFilter (com.alibaba.dubbo.rpc.protocol.dubbo.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:85, AccessLogExtFilter (xxx.qrcode.common.filter.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:82, CatTransaction (com.xxx.log.rpc.dubbo)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:73, ContextFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:138, GenericFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:38, ClassLoaderFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
invoke:38, EchoFilter (com.alibaba.dubbo.rpc.filter)
invoke:72, ProtocolFilterWrapper$1 (com.alibaba.dubbo.rpc.protocol)
reply:104, DubboProtocol$1 (com.alibaba.dubbo.rpc.protocol.dubbo)
handleRequest:96, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header)
received:173, HeaderExchangeHandler (com.alibaba.dubbo.remoting.exchange.support.header)
received:51, DecodeHandler (com.alibaba.dubbo.remoting.transport)
run:57, ChannelEventRunnable (com.alibaba.dubbo.remoting.transport.dispatcher)
runWorker:1145, ThreadPoolExecutor (java.util.concurrent)
run:615, ThreadPoolExecutor$Worker (java.util.concurrent)
run:745, Thread (java.lang)
spring源码-AbstractPlatformTransactionManager
public abstract class AbstractPlatformTransactionManager implements PlatformTransactionManager, Serializable {
public final void commit(TransactionStatus status) throws TransactionException {
if (status.isCompleted()) {
throw new IllegalTransactionStateException("Transaction is already completed - do not call commit or rollback more than once per transaction");
} else {
DefaultTransactionStatus defStatus = (DefaultTransactionStatus)status;
if (defStatus.isLocalRollbackOnly()) {
if (defStatus.isDebug()) {
this.logger.debug("Transactional code has requested rollback");
}
this.processRollback(defStatus);
} else if (!this.shouldCommitOnGlobalRollbackOnly() && defStatus.isGlobalRollbackOnly()) {
if (defStatus.isDebug()) {
this.logger.debug("Global transaction is marked as rollback-only but transactional code requested commit");
}
this.processRollback(defStatus);
if (status.isNewTransaction() || this.isFailEarlyOnGlobalRollbackOnly()) {
throw new UnexpectedRollbackException("Transaction rolled back because it has been marked as rollback-only");
}
} else {
this.processCommit(defStatus); //提交事务
}
}
}
/**
* Process an actual commit.
* Rollback-only flags have already been checked and applied.
* @param status object representing the transaction
* @throws TransactionException in case of commit failure
*/
private void processCommit(DefaultTransactionStatus status) throws TransactionException {
try {
boolean beforeCompletionInvoked = false;
try {
boolean unexpectedRollback = false;
prepareForCommit(status);
triggerBeforeCommit(status);
triggerBeforeCompletion(status);
beforeCompletionInvoked = true;
if (status.hasSavepoint()) {
if (status.isDebug()) {
logger.debug("Releasing transaction savepoint");
}
unexpectedRollback = status.isGlobalRollbackOnly();
status.releaseHeldSavepoint();
}
else if (status.isNewTransaction()) {
if (status.isDebug()) {
logger.debug("Initiating transaction commit");
}
unexpectedRollback = status.isGlobalRollbackOnly();
doCommit(status); //提交事务
}
else if (isFailEarlyOnGlobalRollbackOnly()) {
unexpectedRollback = status.isGlobalRollbackOnly();
}
// Throw UnexpectedRollbackException if we have a global rollback-only
// marker but still didn't get a corresponding exception from commit.
if (unexpectedRollback) {
throw new UnexpectedRollbackException(
"Transaction silently rolled back because it has been marked as rollback-only");
}
}
catch (UnexpectedRollbackException ex) {
// can only be caused by doCommit
triggerAfterCompletion(status, TransactionSynchronization.STATUS_ROLLED_BACK);
throw ex;
}
catch (TransactionException ex) {
// can only be caused by doCommit
if (isRollbackOnCommitFailure()) {
doRollbackOnCommitException(status, ex);
}
else {
triggerAfterCompletion(status, TransactionSynchronization.STATUS_UNKNOWN);
}
throw ex;
}
catch (RuntimeException | Error ex) {
if (!beforeCompletionInvoked) {
triggerBeforeCompletion(status);
}
doRollbackOnCommitException(status, ex);
throw ex;
}
// Trigger afterCommit callbacks, with an exception thrown there
// propagated to callers but the transaction still considered as committed.
try {
triggerAfterCommit(status);
}
finally {
triggerAfterCompletion(status, TransactionSynchronization.STATUS_COMMITTED);
}
}
finally {
cleanupAfterCompletion(status); //提交事务之后，释放资源(其中包括归还连接到连接池)
}
}
类继承图
找到监控点-hibernate事务管理器
从方法调用栈和源码里面可以找到监控点，就是Hibernate事务管理器(HibernateTransactionManager)，因为配置文件里会配置事务管理器。
<!-- transaction -->
<bean id="transactionManager_trade"
class="org.springframework.orm.hibernate3.HibernateTransactionManager">
<property name="sessionFactory">
<ref bean="sessionFactory_trade" />
</property>
</bean>
因此可以通过重写两个方法，来实现监控
1.提交事务方法
2.提交事务之后，释放资源方法
为什么要重写这两个方法？因为spring源码-AbstractPlatformTransactionManager里调用的这两个方法最终都是调用Hibernate事务管理器里的这两个方法，所以只要我们重写Hibernate事务管理器里的这两个方法，就可以获取到调用这两个方法的耗时。
重写方法
package xxx.xxx.common.monitor.dbcp;
import lombok.extern.slf4j.Slf4j;
import org.springframework.orm.hibernate3.HibernateTransactionManager;
import org.springframework.transaction.support.DefaultTransactionStatus;
/**
* hibernate事务监控
* 1.提交事务耗时
* 2.提交事务之后，释放资源(其中包括归还连接到连接池)耗时
*
* @author gzh
* @createTime 2020/12/19 1:19 PM
*/
@Slf4j
public class HibernateTransactionManagerMonitor extends HibernateTransactionManager {
/**
* 提交事务耗时
* @param status
*/
protected void doCommit(DefaultTransactionStatus status) {
long startTime = System.currentTimeMillis();
super.doCommit(status);
long endTime = System.currentTimeMillis();
getDataSourceStatus(endTime-startTime);
}
/**
* 提交事务之后，释放资源(其中包括归还连接到连接池)耗时
* @param transaction
*/
protected void doCleanupAfterCompletion(Object transaction) {
long startTime = System.currentTimeMillis();
super.doCleanupAfterCompletion(transaction);
long endTime = System.currentTimeMillis();
getDataSourceStatus(endTime-startTime);
}
/**
* 写监控数据到cat
* @param durationInMills 耗时
*/
private void getDataSourceStatus(long durationInMills) {
String dataSourceName = "dataSourceName";
try {
int connectionPoolMonitorThresholdTimeout; //获取数据库连接超时时间
//获取apollo配置数据
connectionPoolMonitorThresholdTimeout = MonitorConfig.getSysConfigIntVal("connectionPool.monitor.threshold.timeout.return","100");
StringBuilder sb = new StringBuilder();
sb.append("，归还连接耗时:").append(durationInMills).append("ms");
//归还连接超时监控
if (durationInMills > connectionPoolMonitorThresholdTimeout) {
StringBuilder desc2 = (new StringBuilder("归还连接超时监控，数据源名字:")).append(dataSourceName).append("，阈值:").append(connectionPoolMonitorThresholdTimeout).append(sb.toString());;
String monitorContent2 = desc2.toString();
log.warn(monitorContent2);
MonitorConfig.sendMonitorEvent("connectionPool.monitor.threshold.timeout.return", dataSourceName, monitorContent2, "01");
}
//归还连接耗时监控
StringBuilder desc3 = (new StringBuilder("归还连接耗时监控，数据源名字:")).append(dataSourceName).append(sb.toString());;
String monitorContent3 = desc3.toString();
log.info(monitorContent3);
MonitorConfig.sendMonitor("connectionPool.monitor.connection.time.return", dataSourceName, monitorContent3, "01", durationInMills);
} catch (Exception var12) {
log.error("监控数据源执行情况异常", var12);
}
}
}
