一个小问题,挖出了一个吃了几万美金的bug原创
接手维护的一个项目,原来的开发同事都离职了。我一个代码都没改,服务跑着跑着出bug了。
项目描述:离职的同事交给我维护后,服务一直稳定运行了大半年,且这大半年没有改动代码。接口根据客户端使用的语言下发对应语言的业务数据,各种语言(大概有17种语言)的业务数据由后台任务执行翻译。
某天接口突然没法下发中文数据。
梳理思路,数据最初是从哪里来?
后台跑定时任务,从第三方接口获取英文数据,并将数据翻译成多种语言。流程图如下:
数据缺少了,是任务没执行导致的吗?不,数据库有找到从第三方接口获取到的数据,且日志里有调用第三方接口的记录。
按照上面的流程图,问题可能出现在翻译过程、数据持久化过程。但是根据其它代码的执行情况,排除了数据持久化过程的可能。
那么只剩下翻译过程了,会不会是线程池中出现了排队情况呢?
所有的翻译任务都被提交到一个单线程池中执行,且每次执行前,线程休眠1秒钟。
private ExecutorService translateExecutorService = Executors.newSingleThreadExecutor();
public void translate(TranslateTask translateTask) {
Runnable runnable = () -> {
try {
Thread.sleep(1000);
translateTask.doTranlate();
} catch (Exception e) {
logger.error(e.getMessage(), e);
}
};
translateExecutorService.submit(runnable);
}
掐指一算,这个翻译任务一天的吞吐量最多为60次/分钟6024分钟=86400次。按照业务数据量,一天最多也就500条数据需要翻译。照理来说,处理500条数据应该绰绰有余。
分析了一波,好像一切都是正常的。陷入了困境…
那就将JVM的堆dump出来,剖析剖析。
不看不知道,一看吓一跳。这个线程池中竟让有114258个任务在等待。
这114258个任务从何而来?照理来说一天不会超过500个任务。顺藤摸瓜,找到了一个bug。
原来第三方接口的返回数据中的时间戳为最近一周。而前同事写的代码逻辑:“从数据库加载最近一周的数据,并以时间和语言的组合值放到Set集合中。从第三方接口获取的数据用该Set集合来判断是否已存在。如果不存在,则调用谷歌翻译服务,并将翻译后的数据更新保存到数据库。上述任务每隔5分钟执行一次”。
乍一看这代码,好像没啥毛病。衰就衰在那段时间,调用第三方接口返回的数据中的时间戳出了问题(返回了2015年的时间戳),代码判断数据库不存在该数据,而任务又是五分钟执行一次,导致系统堆积了大量的翻译任务,而本该需要被及时处理的数据只能排队等待,导致缺失了部分语言的数据。最严重的是,程序疯狂地调用谷歌翻译服务,产生了一笔不小的服务费用。
分析此次事故的原因:
-
代码未做容错处理,没有考虑到第三方数据异常的情况。
-
一天内多次调用第三方接口,返回数据都是不变的。很显然,任务的执行周期一天1~2次就行,但任务却被设置成5分钟执行一次。
-
在大量调用谷歌翻译服务时,系统未做监控告警。