背景
在财务同步采购单据时,之前由于门店较少,里面有些问题也没有暴露出来,切完所有门店之后,出现生产bug,经过一系列排查,最终发现是代码写的严谨导致的。现将这次事故记录下来,供大家参考,同时这里要感谢祥哥教的解决问题的思路与方法。等一下也会说这个。
执行流程大致是:1、查询采购库;2、过滤筛选,并分成插入财务表和更新财务表;3、对插入数据进行处理;4、插入财务主表子表;5、对更新数据进行处理;5、更新财务主表字表。运行时间是凌晨3:30。
问题描述
1、在9.9凌晨生产第一次出现问题,
因为当时是周末,而且这个情况当时没有告警邮件(后面两次还是没有告警,这个已经跟ci组说过了,希望他们帮我们排查一下为什么这个没有告警)。10号先网上查了一下,有两个原因1、是jar包版本和服务器冲突;2、是连接长时间不访问,connection失效。然后询问DBA,DBA说第一种不可能,而第二种是我们生产环境连接只有1800s,而查看日志发现我们对于采购的连接间隔确实超过了1800s。但是问题是之前没碰过中间需要这么久的执行时间,而且初步看代码好像也没有问题啊,这个也说明查看源码可能就是看不出问题,必须要仔细分析。因为当时没有打印日志也没有监控方法,所以只知道两次查看sql之间有将近30分钟的时间在运行。
2、那中间30分钟到底干嘛去了呢?有怀疑是不是当时财务cpu被其他什么给占用了,就去跑运维查看当时的运行情况,发现当时cpu运行是20%,不高啊(其实这里还有一个疑问的是运维的cpu到底是按每个核去监控还是每台机器去监控的)。
3、等到12号凌晨的时候,又报这个问题出来了,这时候祥哥说代码应该有问题,然后教了我一种监控代码运行的方式,就是在正常运行的线程外再启一个线程去监控这个运行线程,然后将堆栈信息打印出来,这个点类似jstcak这种命令。只要打印出来的日志发现某个时间间隔以内某个方法打印次数过多,说明这个方法执行缓慢,代码可能有问题。代码如下:
val currentThread = Thread.currentThread() var flag = false val t = new Thread( new Runnable { override def run(): Unit = { while(!flag) { val stackElements = currentThread.getStackTrace logger.info(stackElements.map(_.toString).mkString("\n")) Thread.sleep(1000) } } } ) t.start()
try {
业务处理代码...
} finally{
flag = true
}
定义flag当做监控启停标志,这样就可以控制打印开始于结束。getStackTrace可以获取到堆栈信息。
4、现将9.15凌晨的日志拿来分析,,将所有运行时间超过4s的罗列出来。
03:30:04 运行getInvoiceLine((对插入数据进行处理) 数据条数:(3249与27382) 运行时间: 4s
03:30:09 运行 getCountTupleByInvoiceCode(对插入数据进行处理) 数据条数:27382 运行时间:03:31:01-03:30:09 = 52s
03:31:01 运行 insertInvoice(插入主表) 数据条数:3249 运行时间:7.6s
03:31:09 运行insertInvoiceLine(插入子表)数据条数:49621 运行时间:116s
03:33:06 插入数据逻辑处理完毕:
03:33:09 运行getInvoiceLine((对插入数据进行处理) 数据条数:(5035与99877) 运行时间: 14s
03:33:25 运行 getCountTupleByInvoiceCode(对插入数据进行处理) 数据条数:149970 运行时间: 04:02:05 -03:33:25=1720s
04:02:05 运行 updateInvoiceLine(更新子表) 数据条数:5035 运行时间:12s
04:02:17 运行 updateInvoiceLine(更新子表) 数据条数:99877运行时间:240s
04:06:17 更新数据逻辑处理完毕:
04:06:17 再连接采购库报错
5、这里先分析getCountTupleByInvoiceCode方法,因为插入更新是同一段代码,数据量不同,运行时间差别好大。最终定位到问题是如下代码:
stockOrderItemList.filter(x => x.deliveryOrderItemId == deliveryOrderItem.id && x.`type` == 1).sortBy(_.seqId).reverse
这里stockOrderItemList数据量多的时候,效率特别慢。现将这段代码转换为使用hashmap的形式。同时将sortBy(_.seqId).reverse这种形式使用sql的形式只查询出最小序列号0即可。
6、优化后效果,因为没有发布到生产环境,所以只是在本地测试出情况。将生产环境的数据库拷贝至本地(可能数据量有所变化)。
在时间监控线程运行过程中,时间间隔为1s,getCountTupleByInvoiceCode只出现一次,那么说明这个方法最多执行时间为1s,数据量为118608。由于数据量变化和机器不同,造成执行速度快慢可能有偏差(本地环境updateInvoiceLine 数据条数:68262运行时间:7.8s)所以需要在生产上继续观察。
7、小小总结一下:1、就是对于数据量较大的操作,list.fillter这些操作比较花费时间,尽量避免。
2、对于发生问题,多换个角度思考或者其他工具去解决,然后对于问题可以提出疑问,但尽量少一点猜测,多一点动手。
8、后续问题:1、getInvoiceLine方法依旧是比较慢的:问题代码如下:
//配送单主表子表映射
val deliveryOrderItemMapList = selectDeliveryList.map(x => x -> deliveryOrderItemList.filter(_.deliveryOrderId == x.id))
子表在遍历时需要获取到主表的信息,暂时没想过更好的解决方法。
2、对于数据库操作,已经换成batch操作,依旧是如此缓慢。
3、对于12号凌晨,除了这个问题之外还有一个问题,在上面的报错之前先抛出一个异常,如下:
后期需要继续修复优化。
续:
修复了之前代码getCountTupleByInvoiceCode里面的问题,加上给数据库连接配置加上rewriteBatchedStatements=true
现将9.29凌晨的日志拿来分析,,将所有运行时间超过1s的罗列出来。
03:30:00 查询采购配送单(根据更新时间与验收时间,共查询9585条) 运行时间: 1s
03:30:02 查询采购配送单子单(根据主单id in查询,主单id是索引,但是因为有9585条,所以比较慢,共查询73574) 运行时间: 3s
03:30:05 运行getInvoiceLine:163行:selectDeliveryList.map(x => x -> deliveryOrderItemList.filter(_.deliveryOrderId == x.id)) 数据条数:9585+73574 运行时间:7s
03:30:12 查询出入库子单(使用连表查询,并且使用了in delivery_order_item_id,73574,该字段有idx_delivery_order_item) 数据条数:23393运行时间:3s
03:30:14 运行插入子表addBatch,数据条数:73574 运行时间:5s,其中sql运行时间为:3.2s
03:30:19 插入数据逻辑处理完毕:
03:30:19 查询采购配送单子单(根据主单id in查询,主单id是索引,但是因为有3930条,所以比较慢,共查询80933) 运行时间: 3s
03:30:22 运行getInvoiceLine:163行:selectDeliveryList.map(x => x -> deliveryOrderItemList.filter(_.deliveryOrderId == x.id)) 数据条数:3930+80933运行时间:7s
03:30:30 查询出入库子单(使用连表查询,并且使用了in delivery_order_item_id,80933,该字段有idx_delivery_order_item) 数据条数:121915运行时间:3s
03:30:33 运行更新子表executeBatch,数据条数:121915运行时间:17s,其中sql运行时间为:15.2s
03:30:50 更新数据逻辑处理完毕:
03:30:50 剩下6个processor执行
03:30:55 同步单据处理完毕
小小总结一下:
1、代码问题已经修复,下次需要注意
2、批量插入时需要配置数据库配置,addBatch才能生效。
接下来的问题:
1、selectDeliveryList.map(x => x -> deliveryOrderItemList.filter(_.deliveryOrderId == x.id)) 这种需要思考有没有其他更快的方式替换
2、对于数据库操作,为什么之前的更新操作会比现在慢很多?什么原因导致?
3、对于使用in查询的,即使使用了索引,依旧会如此缓慢?有没有优化方式?
4、时刻注意是否还会有9.12凌晨出现的异常