@transaction 提交事务_spring-如何监控提交事务耗时？

说明

用到的软件是

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)，因为配置文件里会配置事务管理器。

复制代码

因此可以通过重写两个方法，来实现监控

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 */@Slf4jpublic 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);    }  }}复制代码

好了就分享到这里了

原文链接：https://juejin.cn/post/6912455498147201038

如果觉得本文对你有帮助，可以转发关注支持一下