一次程序上线后启动很慢事故分析

问题描述

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

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

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

问题分析

看了本机开发环境和测试环境，启动都很是快，各行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呢？

数据库版本问题？

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

立刻动手！

• 云版本
  • 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当时没这么智能？ 我虽然知道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首发掘金。转载请注明出处。 juejin.im/post/5eaeb1…

2020.5.3 写于家中晚上加班后