性能文章>一个小问题,挖出了一个吃了几万美金的bug>

一个小问题,挖出了一个吃了几万美金的bug原创

3年前
7584110

接手维护的一个项目,原来的开发同事都离职了。我一个代码都没改,服务跑着跑着出bug了。

image.png

项目描述:离职的同事交给我维护后,服务一直稳定运行了大半年,且这大半年没有改动代码。接口根据客户端使用的语言下发对应语言的业务数据,各种语言(大概有17种语言)的业务数据由后台任务执行翻译。

某天接口突然没法下发中文数据。

image.png

梳理思路,数据最初是从哪里来?

后台跑定时任务,从第三方接口获取英文数据,并将数据翻译成多种语言。流程图如下:

image.png

数据缺少了,是任务没执行导致的吗?不,数据库有找到从第三方接口获取到的数据,且日志里有调用第三方接口的记录。

按照上面的流程图,问题可能出现在翻译过程、数据持久化过程。但是根据其它代码的执行情况,排除了数据持久化过程的可能。

那么只剩下翻译过程了,会不会是线程池中出现了排队情况呢?

所有的翻译任务都被提交到一个单线程池中执行,且每次执行前,线程休眠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条数据应该绰绰有余。

image.png

分析了一波,好像一切都是正常的。陷入了困境…

那就将JVM的堆dump出来,剖析剖析。

不看不知道,一看吓一跳。这个线程池中竟让有114258个任务在等待。

image.png

这114258个任务从何而来?照理来说一天不会超过500个任务。顺藤摸瓜,找到了一个bug。

image.png

原来第三方接口的返回数据中的时间戳为最近一周。而前同事写的代码逻辑:“从数据库加载最近一周的数据,并以时间和语言的组合值放到Set集合中。从第三方接口获取的数据用该Set集合来判断是否已存在。如果不存在,则调用谷歌翻译服务,并将翻译后的数据更新保存到数据库。上述任务每隔5分钟执行一次”。

乍一看这代码,好像没啥毛病。衰就衰在那段时间,调用第三方接口返回的数据中的时间戳出了问题(返回了2015年的时间戳),代码判断数据库不存在该数据,而任务又是五分钟执行一次,导致系统堆积了大量的翻译任务,而本该需要被及时处理的数据只能排队等待,导致缺失了部分语言的数据。最严重的是,程序疯狂地调用谷歌翻译服务,产生了一笔不小的服务费用。

image.png

分析此次事故的原因

  1. 代码未做容错处理,没有考虑到第三方数据异常的情况。

  2. 一天内多次调用第三方接口,返回数据都是不变的。很显然,任务的执行周期一天1~2次就行,但任务却被设置成5分钟执行一次。

  3. 在大量调用谷歌翻译服务时,系统未做监控告警。

点赞收藏
分类:标签:
猪杂汤饭
请先登录,查看1条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步
10
1