性能文章>日常问题排查-调用超时>

日常问题排查-调用超时原创

11月前
5501113

前言

日常Bug排查系列都是一些简单Bug排查,笔者将在这里介绍一些排查Bug的简单技巧,同时顺便积累素材^_^。

Bug现场

这次的Bug是大家喜闻乐见的调用超时。即A调用B超过了5s
image.png

搜索一下日志,发现A系统在发出5s后超时。B系统在将近8s后才收到请求,也就是说B系统还没开始处理,A系统就超时了。
image.png

开始排查

那么这5秒钟时间到底消失在哪里呢?有3个可能的点:

1)A日志打点到真正发出请求包
2)网络上
3)B真正接收请求包到B日志打点。
image.png

网络check

首先笔者检查了当时此机器的Net Traffic,发现非常平稳,考虑不是网络的锅。

Full GC

对于Java应用,第二个考虑的点应该是GC,毕竟是Stop The World!笔者于是翻了下对应 A/B系统两台 发现A系统okay,B系统在当时有Full GC,而且长达6s:
image.png
既然监控到了,那么问题基本就是B系统的Full GC了,这个长达6s的full gc让B系统5s后才打印出请求。可是这又引入了一个新的问题,为什么一次Full GC能达到6s之巨。

为什么这么慢

观察监控,笔者发现Full GC有时候快有时候慢。翻出对应6s的那条gc监控日志。

B系统
[Full GC(Metadata GC Thresold) … (class unloading,5.5285249 secs]…[Times: user=0.85 sys=0.07 real=6.26 secs]
class unloading…
发现class unloading竟然会有将近5s。再进一步用awk过滤,最高有10s的,最短有0.1s的,而他们回收的内存大小确差不多。正常Full GC应该不会有这么久,那个0.1s才感觉是正常的,难道当时机器有什么事情发生?带着疑问,笔者继续观察监控曲线,看看能不能找到些蛛丝马迹,找到当时的时间点,发现:
image.png
GC慢的时候,对应机器内存的swap in很高。紧接着找了其它慢的Full GC。发现非常有规律,只要swap in很高Full GC就慢!
于是笔者,就尝试着搜索了一下

https://blogs.oracle.com/poonam/long-class-unloading-pauses-with-jdk8
发现,官方也发现了这个问题,并给予了解释。

为什么会有swap

实际上对应机器的内存使用率并不高,一共8G的内存,JVM只占用到了4G左右。但swap的逻辑并仅仅是内存吃紧了才使用swap分区。如果有一块内存长期不用,也有可能被交换到swap分区。
例如,JVM的class信息,如果一个class MetaData仅仅是存在那里,并不被用到的话。 可能被kernel扔到swap里面。但这时候在GC可达性分析的时候,又会去访问这个MetaData信息,就导致虽然内存利用率不高,但依旧发生使用swap导致慢的情况!
image.png
但是swap里面到底是什么内容,是不是和jvm相关就很难知晓了。所以看上去是概率上出现GC慢的问题。

另一个机房没出问题

这时候巧的是,业务开发向笔者反映,另一个机房的相同应用确不会出现此问题。捞了下对应日志,发现其class unloading只有0.9s左右。笔者观察了下,发现另一个机房的机器并没有用swap。于是笔者比较了一下两个机房关于swap相关的内核参数:

GC慢机器 cat /proc/sys/vm/swappiness 60
GC正常机器 cat /proc/sys/vm/swappiness 1
发现我们新建机房的,我们SA已经预先把swappiness调成了1,意思是告诉kernel尽量不要使用swap,这样就不会有这种swap导致的坑爹问题了。

总结

对于非内存瓶颈的应用,我们应该基于实际情况决定是否把swap禁用掉,以免因swap造成卡顿!另外, 对于一个偶发性的问题,我们应该通过监控等手段去寻找规律,这样就很容易找到突破点。

请先登录,再评论

就怕一直不复现,还到处找不到原因,心慌

310月前
回复 Brian7:

那就let it go~

10月前回复

为你推荐

从一起GC血案谈到反射原理
前言 首先回答一下提问者的问题。这主要是由于存在大量反射而产生的临时类加载器和 ASM 临时生成的类,这些类会被保留在 Metaspace,一旦 Metaspace 即将满的时候,就会触发 Fu
字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
JVM 源码解读之 CMS 何时会进行 Full GC
前言 本文内容是基于 JDK 8在文章[ JVM 源码解读之 CMS GC 触发条件](https://heapdump.cn/article/190389) 中分析了 CMS GC 触发的
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意