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

833 阅读5分钟

问题描述

一个普通的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 innot 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.cn/post/684490…

2020.5.3 写于家中晚上加班后