一次程序上線後啓動很慢事故分析

問題描述

一個普通的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 寫於家中晚上加班後