中午同事过来反馈测试平台的某个执行计划一直处于执行中,但是无结果返回。起初不以为意,认为和前天一样是某个测试用例出现脏数据导致,遂去看后台日志,发现并无报错。
鉴于过往总是被坑,便不死心让同事将计划下的每个测试集合都单独执行一遍,均无问题,此时有些疑惑,但仍认为和平台无关,系使用问题。查看过往执行记录,发现昨日还是好的,首次出现无法执行在今日凌晨。
于是不得不再次本地启动引擎,添加控制台输出,进行观察。发现任务创建后,要过三四十秒才被执行,一开始我认为是任务调度问题,但本地引擎本身并未有其他执行任务。一头雾水下再去看引擎控制台,结果又发现执行任务下发成功后引擎并未收到,最后查看引擎执行日志才看到连接超时。而超时时间我设置了 30s,一个三百多条用例的执行计划没有道理会要这么长的任务计算时间,这种奇怪现象是平台上线三年来首次遇见。
本着先恢复使用的原则,我先调大了任务获取的超时时间。又再三确认同事昨天并未修改测试用例后,便开始仔细回顾昨天自己对于平台的操作,看看是否会影响任务下发时间变长。
而昨日我只做过两件事,一是昨日下午清理了一张有 175G 的测试报告表,并使用 OPTIMIZE TABLE 语句进行重整理(虽然执行失败),但是该表在上传报告才会使用,下发任务理论上不会影响。
二是昨晚上线一个新功能,将原有的 case 表中的 tags 字段,转存到 case_branch 表中,因为平台兼容了一些原来的自动化代码用例,而自动化代码有分支管理,所以 case 表对于 case_branch 表数据是一对多的关系。但平台自身的测试用例没有分支管理,走的代码逻辑也不同,我也并未修改此处代码,况且 case_branch 表是其他同事因另一个需求加的,在上周就已经上线,我只是复用了该表,因此断定与本次发版内容也无关系。
那么究竟问题出在哪,我陷入迷茫,甚至一度怀疑是否昨天清理表数据搞坏了数据库。就这样纠结半小时后,突然想起来报问题的同事说,任务下发变慢有好几天了。于是我又从下发任务过程开始逐步排查 sql 执行日志,最先发现的是某个每秒执行的定时任务有个 sql 较慢,耗时 0.45s 左右,本着尝试原则,调大了定时任务周期,但于事无补。
于是继续排查,又发现任务计算过程中,获取用例详情的 sql 竟需要 0.1s,那三百多条用例可不就要三四十秒。但以前并未有这个问题,昨日也未修改该 sql 相关的内容。去看 git 中该 sql 的修改记录,发现该 sql 上周修改过,正是其他同事在发布 case_branch 表时修改的,修改内容如下:
# 修改前
select xx from case c where c.id=#{id}
# 修改后
select xx from case c
left join case_branch cb on cb.case_id=c.id
where c.id=#{id} limit 1
前面说过,case 表对于 case_branch 表是一对多的关系,因此即便用主键查询,也会返回多条,所以为了结果唯一性,又加入了 limit1。那为何此处会影响性能,又为何在刚上线没有影响呢。
我又去看了这两个表的数据,发现 case 表不过一万多条数据,而 case_branch 表有二十七万条数据,这样一对多的连接,从而导致了查询性能变差。如果去掉此处表连接,那么查询时间仅需 0.005 秒,性能差了几十倍。
那又为何直到今天才会引起明显的性能问题呢,其实也和昨天上线有一定关系。上线后我对 case_branch 表刷了数据,原本同事上线后该表只有几千条数据,而我因为另一个功能需要记录更多的数据,从而导致该性能问题最终在今天暴露。
后续让同事重新写了新的 sql,还原了这条 sql,因为他用这条查询 sql 是针对极少数的特有数据,且处理逻辑不同,因此单条 sql 即使在 0.1 秒也能接受。
重新上线后,再次执行该计划,果然在一秒多就完成了任务计算并下发,至此问题得到解决。