问题现象

现有表data_type_test

CREATE TABLE `data_type_test` (
  `id` int NOT NULL AUTO_INCREMENT,
  `ext1` varchar(32) CHARACTER SET utf8 DEFAULT NULL,
  `ext2` double DEFAULT NULL,
  `ext3` decimal DEFAULT NULL,
  PRIMARY KEY (`id`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8mb4;

实体对象

@ToString
@Data
public class NoMatchDataType {

   private int id;

   private String ext1;

   private Double ext2;

   private BigInteger ext3;
}

定义一个接口，查询全表（全表总记录400条）。

@GetMapping("noMatchType")
public void noMatchType() {
   jdbcTemplate
         .query("select id, ext1, ext2, ext3 from data_type_test",
               new BeanPropertyRowMapper<>(NoMatchDataType.class));
}

此接口在Jmeter并发测试下，平均耗时竟然可达2.4s（机器比较老旧，一般机器耗时应该在1.3s）。

原因定位

虽然此处是进行一次全表查询，但由于表只有4列，且总条数为400条。耗时理应是到不了2.4s的。

通过arthas使用trace命令，分析方法耗时，发现操作数据库执行SQL语句，返回结果集，耗时并不多。反而在org.springframework.jdbc.core.BeanPropertyRowMapper#mapRow中耗时颇多。

继续trace，确认是org.springframework.jdbc.core.BeanPropertyRowMapper#getColumnValue(java.sql.ResultSet, int, java.beans.PropertyDescriptor)在某几次调用时，耗时剧增。

分析代码，发现org.springframework.jdbc.support.JdbcUtils#getResultSetValue(java.sql.ResultSet, int, java.lang.Class<?>) 在执行

getResultSetValue(rs, 4, BigInter.class);

由于数据类型不匹配，导致方法内部会产生一个异常。

修改代码

@GetMapping("matchType")
public void matchType() {
   jdbcTemplate
         .query("select id, ext1, ext2, ext3 from data_type_test",
               new BeanPropertyRowMapper<>(MatchDataType.class));
}

再次进行测试，发现此时接口耗时仅需160ms（机器比较老旧，一般机器耗时应该在80ms），性能提升了10倍有余。

同时，BeanPropertyRowMapper上也标注了

Please note that this class is designed to provide convenience rather than high performance. For best performance, consider using a custom {@link RowMapper} implementation

因此若需要更好的性能时，还可以自定义RowMapper。

拓展分析

回顾问题，可以发现，本次问题的根本原因是程序在高频产生异常。

查看Exception代码，发现其构造函数中，调用了fillInStackTrace方法，用以填充执行堆栈跟踪。

public synchronized Throwable fillInStackTrace() {
    if (stackTrace != null ||
        backtrace != null /* Out of protocol state */ ) {
        fillInStackTrace(0);
        stackTrace = UNASSIGNED_STACK;
    }
    return this;
}

此方法需要填空执行栈，是一个重量级开销的方法。同时方法的消耗还与调用链的深度相关。

protected Exception(String message, Throwable cause,
                    boolean enableSuppression,
                    boolean writableStackTrace) {
    super(message, cause, enableSuppression, writableStackTrace);
}

我们可以通过设置writableStackTrace来标识是否需要记录栈，以减少资源的开销。

比如发生一些业务异常的时候（校验失败，内容非法），只需要一个描述信息方便感知，而不需要异常栈。

简单的写一个用例，通过基准测试来验证下性能差距。

public class BusinessException extends RuntimeException {

   private Integer code;

   private String msg;

   public BusinessException(Integer code, String msg) {
      super();
      this.code = code;
      this.msg = msg;
   }

   public BusinessException(String msg) {
      super(msg, null, false, false);
      this.msg = msg;
   }
}

public class Test {

   public static void main(String[] args) {
      deep1(2);
   }

   public static void deep1(int i) {
      deep2(i);
   }

   public static void deep2(int i) {
      deep3(i);
   }

   public static void deep3(int i) {
      deep4(i);
   }

   public static void deep4(int i) {
      deep5(i);
   }

   public static void deep5(int i) {
      deep6(i);
   }

   public static void deep6(int i) {
      deep7(i);
   }

   public static void deep7(int i) {
      deep8(i);
   }

   public static void deep8(int i) {
      if (i == 1) {
         simpleException(2);
      }
      else {
         fullStackException(2);
      }

   }

   public static void simpleException(int i) {
      if (i % 2 == 0) {
         throw new BusinessException("错误数据.");
      }
   }

   public static void fullStackException(int i) {
      if (i % 2 == 0) {
         throw new BusinessException(101, "错误数据.");
      }
   }
}

@BenchmarkMode({ Mode.Throughput, Mode.AverageTime })
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@State(Scope.Thread)
@Warmup(iterations = 3, time = 1, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Fork(2)
@Threads(5)
public class BenchmarkExceptionTest {

   @Benchmark
   public void deepSimpleException() {
      try {
         Test.deep1(1);
      }
      catch (Exception e) {
      }
   }

   @Benchmark
   public void deepFullStackException() {
      try {
         Test.deep1(2);
      }
      catch (Exception e) {
      }
   }

   @Benchmark
   public void simpleException() {
      try {
         Test.simpleException(2);
      }
      catch (Exception e) {
      }
   }

   @Benchmark
   public void fullStackException() {
      try {
         Test.fullStackException(2);
      }
      catch (Exception e) {
      }
   }

   public static void main(String[] args) throws Exception {
      Options opts = new OptionsBuilder()
            .include(BenchmarkExceptionTest.class.getSimpleName())
            .resultFormat(ResultFormatType.CSV)
            .build();
      new Runner(opts).run();
   }
}

Beanmark结果

Benchmark                                       Mode  Cnt     Score    Error   Units
BenchmarkExceptionTest.deepFullStackException  thrpt   10     0.003 ±  0.001  ops/ns
BenchmarkExceptionTest.deepSimpleException     thrpt   10     0.164 ±  0.018  ops/ns
BenchmarkExceptionTest.fullStackException      thrpt   10     0.003 ±  0.001  ops/ns
BenchmarkExceptionTest.simpleException         thrpt   10     0.159 ±  0.013  ops/ns
BenchmarkExceptionTest.deepFullStackException   avgt   10  1614.045 ± 97.780   ns/op
BenchmarkExceptionTest.deepSimpleException      avgt   10    29.884 ±  2.117   ns/op
BenchmarkExceptionTest.fullStackException       avgt   10  1432.695 ± 83.864   ns/op
BenchmarkExceptionTest.simpleException          avgt   10    30.635 ±  0.885   ns/op

可以看到，simpleException与fullStackException的耗时差距。

记一次Spring JdbcTemplate异常耗时排查

问题现象

原因定位

拓展分析