性能文章>【全网首发】MQ-消息堆积-业务线程阻塞案例分析>

【全网首发】MQ-消息堆积-业务线程阻塞案例分析原创

324729

业务背景

业务中某个应用在消费MQ的时候,出现部分机器消息堆积,随着时间推移,堆积的机器数量越来越多,消息的堆积总量越来越多。

问题现象

系统监控

CPU、Load、内存、网络、磁盘监控指标正常;JVM 内存、GC正常。

MQ监控

1.111.png

分析过程

MQ消息堆积最常见的情况是:
应用侧处理MQ消息比较慢,触发了MQ的流控机制(MQ在统计到应用消费慢的时候,会逐步减少给应用侧的消息,最糟糕的情况是MQ一条消息也不会发给应用来消费)。

接下来的思路是慢在了哪?

  • 在业务监控完备的情况下,通过分析业务监控指标,可以粗略定位异常点
  • 明确运行的程序在忙些什么,分析线程堆栈信息

堆栈信息

image.png
上面图片中,TID=562的线程正在read Oracle返回的信息。经过观测,TID=562的线程一直处于上面图片中的状态。由于上面图片中的堆栈信息不完整,所以使用jstack抓取后分析出一个关键信息:

locked oracle.jdbc.driver.T4CConnection@31c02e79

T4CConnection分析

【oracle.jdbc.driver.T4CConnection@31c02e79】是与Oracle交互的数据库连接对象,需要分析出

  • 该连接对象对应的socket信息
  • 该连接对象正在执行的SQL
  • 该连接对象关联的statements对象信息

T4CConnection信息

image.png

Socket信息

311.png
获取到Socket信息进行了如下几个方面的分析:
该Socket与Oracle服务端交互情况:
411.png

//通过tcpdump分析与Oracle服务端交互的报文,发现该连接上没有任何报文交互
tcpdump -i any tcp and port 45556 -A -nn

问:与Oracle DBA确认该Socket在服务端正在执行什么SQL?
答:没找到任何关于该Socket的信息

SQL信息

通过分析oracle.jdbc.driver.T4CConnection类代码及【oracle.jdbc.driver.T4CConnection@31c02e79】属性信息找到了正在执行的SQL及与该连接关联的statements信息:
SQL:
511.png
statements:
image.png
到此,我们分析出了引起线程阻塞的SQL详情。

解决办法

  • 对参数是null的情况进行过滤,不再向Oracle发送这样的SQL语句;同时日志里对这种异常情况进行记录,以便更细致的分析数据为null的产生场景。
  • 加强应用可观测性之线程执行耗时监控
    ○ 在业务逻辑开始的前面,添加一个filter
    ○ 当请求到达filter的时候,将当前线程及此时的时间记录到一个Map中
    ○ 当请求结束回到filter的时候,将当前线程从Map中删除
    ○ 单独起一个定时任务来遍历Map,当发现Map中某个线程执行时间超过阈值,就打印出线程的堆栈
    ○ 当开发人员收到异常堆栈的报警,人工介入进行系统恢复及问题快速定位
点赞收藏
大禹的足迹

在阿里搬了几年砖的大龄码农,头条号:大禹的足迹

请先登录,查看2条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

【译】处理阻塞调用的两种方法:线程并发与网络异步

【译】处理阻塞调用的两种方法:线程并发与网络异步

【全网首发】MQ-消息堆积-JDK Bug导致线程阻塞案例分析

【全网首发】MQ-消息堆积-JDK Bug导致线程阻塞案例分析

【全网首发】SSL Session默认设置导致线程阻塞了几十秒的案例分析

【全网首发】SSL Session默认设置导致线程阻塞了几十秒的案例分析

【全网首发】一次 Java log4j2 漏洞导致的生产问题

【全网首发】一次 Java log4j2 漏洞导致的生产问题

9
2