记一次线上问题解决过程

背景

          在财务同步采购单据时，之前由于门店较少，里面有些问题也没有暴露出来，切完所有门店之后，出现生产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凌晨出现的异常