springboot程序启动时很慢详细分析过程

问题描述

一个普通的springboot程序，本机和测试环境都没问题。上线到公司云环境后也一直安然无事。

今天重启一下，发现重启的时间不对劲，非常慢。此时我的手掌心已经有点冒汗。这个程序大部分是我写的，也是我上线的。

还好现在仍未全线推广，我迅速镇静下来，复看了之前的启动日志，方才发现一直启动都很慢，只是之前启动好了就没有管他，因此好不察觉。

问题分析

启动的时候会有一些业务逻辑，通过@Order依次执行。看了本机开发环境和测试环境，启动都非常快，各行info日志打印都在一秒以内。

而云环境的日志都很不正常，特别在某一行的日志打印卡住了很久，足足用了82秒。

问题定位的范围已缩小，就是这里有问题。

这一段逻辑大概就是100行代码：主要的工作就是查询几次数据库，有一些嵌套循环，放一些数据到内存。仅此而已。

问题定位

由于各个环境的代码、数据库数据、操作系统等基本都是类似的，一时没有头绪。

更麻烦的事情大家都知道，线上的故障是不好断点定位排查的，恰恰测试环境又没问题，无法IDEA调试，线上也不能随意加日志排查，最怕这种故障。

逐一分析吧。

嵌套循环引起？

我首先怀疑是不是嵌套循环指数级增加了，或者死循环了。于是查看了数据库里的数据是一致的，因此循环肯定也是一样的，既然测试环境没有死循环，那么云环境肯定也不会死循环。

网络引起？

排除了循环问题，然后我就重点怀疑连接数据库这里了。
环境不同，那必然网络也不同，是不是云环境的程序主机连接数据库主机的网络有问题？连了一分多钟？
马上测试了一下，也不是。

主机性能太差？

我接着怀疑过是否主机性能太差？不过念头一过就否定了，线上环境怎么会比测试环境差。

随后我验证了一下，线上的配置还是很不错的。

SQL引起？

接着，我只能怀疑是不是sql查询过慢了。虽然数据一样，这个不太可能。不过这段代码的sql不多，我逐一拿出来试了一下，谁知道尝试第一条sql就卡住了！拿到navicat里跑竟然要一分多钟。

罪魁祸首找到了，就是这条sql。

select * from td_b_noderelation a where a.exroadnodeid not in (
    select enroadnodeid from td_b_noderelation b 
    where b.version=a.version
);

其实这么多年工作经验，每次变慢的原因九成九就是sql引起，我早就应该首先怀疑它了。
不过话又说回来，数据一样，怎么会一个环境慢，一个环境快呢？

执行计划?

sql慢，首先想到的当然是执行计划。

explain select * from td_b_noderelation a where a.exroadnodeid not in (
    select enroadnodeid from td_b_noderelation b 
    where b.version=a.version
);

• 云环境

id    select_type    table    type    possible_keys    key    key_len    ref    rows    Extra
1    PRIMARY    a    ALL                    17598    Using where
2    DEPENDENT SUBQUERY    b    ALL                    17598    Using where

• 测试环境

id    select_type    table    partitions    type    possible_keys    key    key_len    ref    rows    filtered    Extra
1    SIMPLE    a        ALL                    17382    100    
1    SIMPLE    <subquery2>        eq_ref    <auto_distinct_key>    <auto_distinct_key>    93    billing.a.exRoadNodeId,billing.a.version    1    100    Using where; Not exists
2    MATERIALIZED    b        index    PRIMARY    PRIMARY    141        17382    100    Using index

奇怪了，一样的数据，怎么云环境用了ALL呢？

Explain - select_type

select_type：查询中每个select子句的类型

• (1) SIMPLE(简单SELECT，不使用UNION或子查询等)
• (2) PRIMARY(子查询中最外层查询，查询中若包含任何复杂的子部分，最外层的select被标记为PRIMARY)
• (3) UNION(UNION中的第二个或后面的SELECT语句)
• (4) DEPENDENT UNION(UNION中的第二个或后面的SELECT语句，取决于外面的查询)
• (5) UNION RESULT(UNION的结果，union语句中第二个select开始后面所有select)
• (6) SUBQUERY(子查询中的第一个SELECT，结果不依赖于外部查询)
• (7) DEPENDENT SUBQUERY(子查询中的第一个SELECT，依赖于外部查询)
• (8) DERIVED(派生表的SELECT, FROM子句的子查询)
• (9) UNCACHEABLE SUBQUERY(一个子查询的结果不能被缓存，必须重新评估外链接的第一行)

Explain - type

type：对表访问方式，表示MySQL在表中找到所需行的方式，又称“访问类型”。
常用的类型有： ALL、index、range、 ref、eq_ref、const、system、NULL（从左到右，性能从差到好）

• ALL：Full Table Scan， MySQL将遍历全表以找到匹配的行
• index: Full Index Scan，index与ALL区别为index类型只遍历索引树
• range:只检索给定范围的行，使用一个索引来选择行
• ref: 表示上述表的连接匹配条件，即哪些列或常量被用于查找索引列上的值
• eq_ref: 类似ref，区别就在使用的索引是唯一索引，对于每个索引键值，表中只有一条记录匹配，简单来说，就是多表连接中使用primary key或者 unique key作为关联条件
• const、system: 当MySQL对查询某部分进行优化，并转换为一个常量时，使用这些类型访问。如将主键置于where列表中，MySQL就能将该查询转换为一个常量，system是const类型的特例，当查询的表只有一行的情况下，使用system
• NULL: MySQL在优化过程中分解语句，执行时甚至不用访问表或索引，例如从一个索引列里选取最小值可以通过单独索引查找完成。

数据库版本问题？

百思不得其解之际，我想到了云环境是上线前才找人搭建的，而测试环境是去年就搭建好的，两个环境的数据库版本会不会根本不一样？

马上动手！

• 云版本

  • select @@version
  • 5.6.30-log

• 本机/测试环境

  • select version()
  • 8.0.18

我晕，怎么弄了个5.6这么落后的版本？想稳定也至少用个5.7啊。

先了解一下这两个版本的历史：

• 5.6.30是2016年的了
• 8.0.18 2019年10月

ps:最新好像8.0.19 2020年1月的

2016年这么历史悠久，会不会当时的还没有eq_ref这个type？这是我首先怀疑的。然而查看msyql官网，并不是，这个type早就有了。

not in写法问题？

那会不会是优化器问题？5.6当时没这么智能？
在5.5之前，关联查询基本总是要优于子查询，但是5.5以后已经不是这样了。
在5.6和8.0，我虽然知道not in大多数情况比not exists差不多或者更优，但我还是尝试了一把not exists。

explain select * from td_b_noderelation a where not exists (
    select 1 from td_b_noderelation b 
    where b.version=a.version and a.exRoadNodeId=b.enRoadNodeId)

然而执行计划没有任何变化。证明现在的版本已经和5.5版本那时候不太一样了，优化器已经大多数情况会优化not in和not exists了。

那问题究竟出在哪里？

我重新理了一下思路，回看了一下之前的执行计划，发现我漏了很重要的一点，测试环境的type是index！

总不会是建表语句不同吧?
带着这个疑问，我show create table查看。

CREATE TABLE `td_b_noderelation` (
  `enRoadNodeId` varchar(16) COLLATE utf8_bin NOT NULL ,
  `exRoadNodeId` varchar(16) COLLATE utf8_bin NOT NULL ,
  `miles` decimal(12,0) DEFAULT NULL ,
  `version` varchar(13) COLLATE utf8_bin NOT NULL ,
  `validTime` varchar(19) COLLATE utf8_bin DEFAULT NULL ,
  PRIMARY KEY (`enRoadNodeId`,`exRoadNodeId`,`version`),
  KEY `idx_td_b_noderelation_01` (`version`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin 

CREATE TABLE `td_b_noderelation` (
  `enRoadNodeId` varchar(16) COLLATE utf8_bin NOT NULL ,
  `exRoadNodeId` varchar(16) COLLATE utf8_bin NOT NULL ,
  `miles` decimal(12,0) DEFAULT NULL ,
  `version` varchar(13) COLLATE utf8_bin NOT NULL ,
  `validTime` varchar(19) COLLATE utf8_bin DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin 

我晕，竟然是建表的人忘了建主键和索引。这也太坑爹了。
建了主键，问题迎刃而解。

最后

疑问

这张表也就8万数据，小表，没有索引查也慢不了哪去。为什么会慢的这么离谱？

原因就是这个自关联，本身很小，笛卡尔就上亿了，怎能不慢。

总结

这张表虽然是小表，平常也很少查（都放到内存里了），所以一般也发现不了。但是数据库规范和工作态度认真真的太太重要了。还好是启动时问题，如果发生在算费或者交易时，就完蛋了。

我自己水平也有限，不能在开始一眼看出问题，分析了半天。

通过这个总结，警醒后人与后事吧。

本文Danni3发于segmentfault。转载请注明出处。
https://juejin.im/post/5eaeb1...

2020.5.3 写于家中晚上加班后