故障现象
问题影响时间：
钉版：09:50-10:30 11:00-12:00 14:30-15:30 16:00-16:30
ng版：09:40-10:00 11:00-11:30 12:00-12:30 14:30-15:00 16:00-16:30
现象：报销单提单卡顿，数据库连接池耗尽。
恢复情况：16:30 全线恢复访问
故障处理过程
09:03 dyna 告警，连接数不够
都是dyna的线程数不够，这次没有重启实例。看起来只是线程数用的比较多
不过目前sizeWarn是40%就开始报警，是不是可以试着调高一些。
09:52 运维在群里提供了dyna 服务的dump 信息，并且第二次重启dyna服务。
10:12 dyna 服务恢复正常
在此之前，我们一直都认为是dyna 服务的卡顿导致系统的卡顿。
10:58 业务告警群出现响应时间超过500ms 的告警
11:07 研发查看日志发现是xxx-pro有一台响应时间比较长
11:08出现dt无法连接数据库告警
11:15 研发查看数据库会话管理,发现有400多条异常会话。研发查看数据库发现有较多慢sql,从慢sql的数量和执行时间来看不是主要的原因
11:23 研发查看日志,发现是数据库连接池满了
11:25 查看链路追踪的应用详情,发现有4台服务器响应时间过高
11:26 运维重启了这些异常的xxx-pro服务,11:35左右dt-prod恢复正常。
在重启之前志成导出了其中一台异常的xxx-pro服务的stack，
12:00 研发查看了stack文件，发现由http、taskExecutor和smartApproveTaskExecutor这几个线程数加起来的合计线程数达到了接近400个，而数据库的线程最大值只设置了100。猜测可能是因为昨天晚上发版的时候临时加了几个线程池引起数据库线程不足的情况，研发把xxx-pro的数据库连接池最大值调成了200，对xxx-prod和xxx-prod的xxxx-pro分别进行部署,于12:40左右部署完成。
下午14:30左右研发查看xxx-prod数据库会话管理,发现异常会话达到了1K多条，先通过手动杀线程的方式处理
14:43出现了数据库连接池占满的情况
对早上导出的线程明细进行了分析,发现等待线程中datahubGrpcService的调用占了大部分
15:00 对这里的异步线程池策略进行了调整，新增了一个线程池，3点左右分别对dt-prod和ng-prod的xxxx-pro进行部署,部署之后异常会话消除。
private final ExecutorService DATAHUB_SERVICE_POOL =
new ThreadPoolExecutor(5, 20, 30, TimeUnit.SECONDS, new ArrayBlockingQueue<>(50),
new NamedThreadFactory("datahub-service-pool"), new ThreadPoolExecutor.CallerRunsPolicy());
过了一会，ng 版提单卡顿，通过链路追踪的功能去定位当前耗时比较长的请求
15:40 通过日志定位，没有发现什么异常，联系运维同学导出当前机器的堆栈信息
通过上面观察，xxx-service-pool 有77个线程在等待，而创建的线程池只有70个，线程开始等待，导致系统卡顿。
注释掉submit 方法中，关于xxx.fetchBillDetailByFormDataCode 方法。半小时后，问题解决。
故障原因
datahubServiceImpl: public void asyncFetchBillDetail(String entCode, String userCode, String formDataCode) { DATAHUB_SERVICE_POOL.execute(()-> dataHubGrpcService.fetchBillDetail(entCode,userCode,formDataCode)); } /** * 生成账单明细 * @param entCode 企业code * @param userCode 用户code * @param formDataCode 报销单code */ public void fetchBillDetail(String entCode,String userCode,String formDataCode) { logger.info("{}/{} fetchBillDetail with formDataCode {}",entCode,userCode,formDataCode); var request = DatahubService.BillDetailFetchV2Request.newBuilder() .setEntCode(entCode) .setOperator(userCode) .setFormDataCode(formDataCode) .build(); callGRpcService(servicePrx -> servicePrx.fetchBillDetailByFormDataCode(request)); } datahub 的grpc 接口实现类 /** * 根据报销单号获取账单明细 * @param request * @param responseObserver */ @Override public void fetchBillDetailByFormDataCode(DatahubService.BillDetailFetchV2Request request, StreamObserver<Empty> responseObserver) { try { List<DatahubBill> datahubBills = billService.listBillByFormDataCode(request.getEntCode(), request.getFormDataCode()); if(CollectionUtils.isEmpty(datahubBills)){ return; } List<String> dhBillCodes = datahubBills.stream().map(DatahubBill::getCode).collect(Collectors.toList()); billService.fetchBillDetail(request.getEntCode(),request.getOperator(),dhBillCodes); responseObserver.onNext(null); responseObserver.onCompleted(); } catch (Exception e) { logger.warn("exception when fetchBillDetail {}",e); responseObserver.onError(Status.UNKNOWN.withDescription(e.getMessage()).withCause(e).asRuntimeException()); } }
问题代码在第13行，如果没有关联月结账单，直接就return，没有关闭grpc 请求的流。
反思与改进方案
代码层面：
- 开发的时候没有考虑周全。为了让代码逻辑收敛、和对接口client 端友好，临时把两个接口合并成一个，在合并两个请求的时候按照通常的逻辑，直接return，没有注意到流的关闭。
- 自测的时候没有发现问题。在本地写自测用例，没有通过grpc 接口，重现不了。合到uat自己测试了几次，因为有线程池的存在，自己没有复现出来。
- 问题的定位分析。之前定位分析问题的时候，把自己的思路局限在了日志、ARMS 还有数据库的健康状态。这个问题涉及到线程的阻塞，很通过上面的方式直接定位到。还需要通过堆栈信息找到根本原因。
- 异步调用没有加链路监控，通过链路追踪无法排查
对策：
- 在方案设计的时候周全一点，不一定要用线程池做异步，还可以用mq。
2. taskExecutor 类的滥用，目前系统中有超过100处的使用，后续可以根据具体的场景，判断是否需要使用单独的连接池。
3. 对于异步调用, 增加日志链路监控。在项目中封装一个tracableTread 类，继承这个类，异步线程也可以实现链路追踪。
4. grpc 远程调用的设置超时时间，根据服务选择合适的超时时间。修改AbstractBaseGRpcService，用户可以自定义超时的时间。
5. grpc 服务端，需要统一下grpc服务端的写法规范。这里后续跟基础架构部的同事沟通下，最好是能够封装到service-common 中。
