JAVA应用不定时卡顿问题排查过程记录

问题描述

服务上线后，接口不定时超时

• 服务不可用时间可以长达6-10秒，但是似乎没有完全不可用，有一部分请求可以成功
• 服务有多台机器，但是同一时间只有一台机器有问题
• 同时redis也会超时，但是redis超时时间是1s，实际使用了远大于1s的时间
• 一些同步阻塞队列设置了100ms的超时时间，实际没有被唤醒
• 总体来说感觉有点类似gc时STW的情况

查看监控

• GC的监控，没有长时间的暂停
  
• redis的写入耗时监控，确实时间很长
  
• dubbo接口线程池打满时自动打印了堆栈，查看关键线程的堆栈
• redis的io线程
  
• 业务线程
  
• 设置了睡眠时间的线程，没有在应该被唤醒时自动唤醒
  

分析过程

• 通过监控可以看到，io线程似乎都在等待io，睡眠线程也在正常睡眠，但是为什么会突然停住？
• 一般常见的原因有GC,CPU打满。gc已经看过了没有长时间gc
• 那么是否是因为短时间的cpu达到100%导致呢，由于我们的监控是分钟级监控，在监控上没有看到明显的变化，不代表秒级的cpu很高
• 于是让运维在机器上每秒抓取vmstat的数据
  
• 可以看到在问题发生的时间段内，数据有明显的变化。运行任务数只有1，不可中断任务数为变成0，cpu使用率是7，明显低于正常状态的数据。线程切换次数也从正常20w变成只有几百。
• 到这里已经非常奇怪了，为什么任务都不执行了？为什么卡主了？
• 当时考虑的方向有，网络阻塞，线程锁，内存回收抖动
• 于是又增加了内存脏页刷新数据的抓取，ping网络的数据抓取
  
• 可以看到问题时间内内存脏页也基本不变化了，说明不是问题原因
• 网络延迟在问题时间段没有任何变化，网络没有问题
• 锁的问题在线程堆栈文件中看过了，基本没有锁存在
• 刚才考虑的方向基本都不是问题，最后想到，那个在卡顿时间内一直在执行的任务是什么任务？为什么它能执行？
• 于是让运维每秒抓取top命令中R状态的线程
  
• 查看问题时间段内在执行的线程终于发现了24861这个线程
• 查看这个线程的线程栈
  
• 一开始看到这个线程的线程栈时非常诧异，因为我们对外提供的是DUBBO接口，没有http接口访问。但这个线程是http接口线程，不应该有访问
• 仔细查看堆栈发现是普罗米修斯拉取监控数据时的http请求
• 普罗米修斯生成监控数据时会获取线程信息，可能会导致线程暂停
• 那么会不会是这个原因导致？

问题确认

• 首先从上面的top命令截图中可以确认，http请求线程开始执行的时间点就是问题开始的时间点，http请求线程结束的时间点也是问题恢复的时间点。从时间上来看完全符合

• 查看历史dubbo打印的线程堆栈，搜索拉取线程的代码sun.management.ThreadImpl.getThreadInfo。发现每次堆栈中都有对应的代码堆栈。由此可以基本确认这个就是问题的根源

• 后续又核对了几次问题发生时的情况，最终确认了这个就是源头。并且线程数量越多，该问题就越频繁。我们的应用有大概3000个线程，因此频繁触发此问题

• 问题发生总结：首先由普罗米修斯通过http请求拉取监控数据，获取数据时会触发获取线程信息。然后所有线程都会暂停由一个name为VM Thread的jvm线程执行，执行时间会有几秒不等，http请求结束后卡顿结束

疑问（是否有大佬解答一下）

• 获取线程信息时会导致部分线程停顿还是全部线程停顿？
• 获取线程信息是纯内存操作，即使有3000个线程感觉也不需要6秒时间。为什么会如此耗时。不同线程进入安全点的时差导致的吗？

后记

• dump 线程堆栈时是通过VM Thread线程执行的，所以不管有几个cpu，也只能有一个cpu在运行（上面问题vmstat日志里可以看到问题发生时间段内只有一个运行任务），所以在大规格的机器上运行有许多线程的java应用，这个问题的卡顿时间也越长
• dubbo框架的线程池打满时也会触发dump 线程堆栈（或其他dump 线程堆栈操作），因此可能会导致短时间的一个卡顿转化为一个长时间的卡顿