记一次高并发服务的FULL GC问题排查与修复(2/2)

暨年终总结

Posted by LEODPEN on 2022-12-31

问题回顾

上一篇说到,我通过调整动态晋升年龄阈值n,保证了服务在高峰期也是能让老年代内存占用以较低速度上升,但同时发现在高峰期的弹性机器总是“出道即巅峰”(即刚刚弹出就将full gc)

高峰期如果经常出现弹性的单机问题(尤其是交易链路)无疑是不太能接受的。

问题分析

被“冤枉”的弹性机器与有意思的类 - 不常见的Finalizer们

发现所有的弹性机器都有相关问题,且每天如此,这不能说是巧合。于是看发布时普通机器情况,原来也有相同问题 —— 服务在刚部署启动时,内存占用会飙升,不一会儿便full gc。

无法直接判断问题所在,我找了一台特定弹性机器,在其full gc 前后分别dump内存。

这是full gc后的内存情况,较正常,说明一次 full gc后服务归于正常,这也和实际情况相符。

在gc前的内存的dump中很直观的发现了一些不常见的类名:

java.lang.ref.Finalizer, java.util.zip.ZStreamRef, java.util.zip.Inlater

Finalizer对象明显较多,此种对象至少得经理两次GC才能被回收,因为需要先让FinalizerThread先执行一次finalize方法才能被下次gc回收掉,但是有可能这中间时间过长,导致gc已过多次而一直未执行finalize方法,那么Finalizer们可能直接飞升老年代去引发full gc。

接着看dump内容,发现被包装为Finalizer的对象蛮多的,有正常的SocksSocketImpl(网络连接)、FileOutputStream(文件流)之流,不过这些都需要有操作系统有直接交互,占用着外部资源,需要额外维护与释放,没啥问题。在众多实例中,部分对象跳了出来:

超级多的Inflater实例,以及ZipFile$ZipFileInputStream,ZipFile$ZipFileInflaterInputStream,还有JarFile(自然其均是重载了finalize方法)。且ZipFileInputStream 以及 ZipFileInflaterInputStream均为java.util.zip.ZipFile的内部类。

由注释等可知ZipFileThis class is used to read entries from a zip file.) 以及 InlaterThis class provides support for general purpose decompression using the popular ZLIB compression library.)用处主要在于去解压文件信息。(且在gc后几乎无上方所提及得zip相关内容)

作出推断,服务在启动时有一些文件被疯狂解压,然后生成了一大堆文件解压的相关类实例,它们作为Finalizer对象不能及时被回收,在一次又一次的young gc后依旧存活,直到跑进老年代使得其猛涨。

不得不说,ZStreamRef在jdk11里面就没了,而且这玩意儿还有死循环的问题:https://bugs.openjdk.org/browse/JDK-8193682

逮捕元凶 - Jetty

就着上面的猜想,首先在代码中看有无直接调用方法去解压某些上传or下载的内容,发现并没有。
接着感觉是某一个插件把目录下Jars都解压了一遍,排查并询问了近期新引入jar包的同学们,却并未有太多头绪,情况一时间僵住。

还是得自力更生,对着dump文件一顿操作,发现jar名字相关的Finalizer对象有JarFileInlfaterUrlJarFile等等,尤其时在gc前JarFile数量极多。此外,我发现了gc前出现了一个可疑的名字JarFileResource。点进一看,发现其全限定名为org.eclipse.jetty.util.resource.JarFileResource
(注:该服务使用的Web容器为Jetty而非Tomcat

也可以看到其属性_path有指向特定的class,且_jarUrl指向了/web/INF/lib/目录下某个具体的jar包,由此做出推断,一个JarFileResource对象就对应这一个jar包的一个类或者说一个文件,是在服务部署启动时Jetty组件疯狂解压jar包的罪证(产物证明)。

注:注意观察路径为/web/INF/lib/且jarUrl前缀为jar:/file

既然问题点已经基本锁定,则有多种办法继续推进:直接Google搜索相关信息看下有无类似情况,直接打开jetty.xml线下修改配置并调试(前提是比较了解),或者是先再排查下可能切入点。

由果溯因 - 从代码到代码

如果觉得代码分析内容过长,可跳过 “由果溯因 - 从代码到代码”部分内容

Jetty整体来说就是由多个Connector,多个Handler以及一个Threadpool组成的,前者可用于实现Http服务器(有着IO模型、应用协议等的封装),后者则是可以实现Servlet容器等,不过不像Tomcat每个连接器都有自己的线程池,Jetty中是大家共享一个全局的(其他二者实现的区别例如service概念,二者如何监听不同端口等等不再展开)。

当然,handler才是Jetty灵魂所在,其使得Jetty非常灵活(依旧具体不展开),如果说有地方在服务启动时疯狂解压jar包,那么一定只能是handler中找,因此可以目光直接看向配置文件Jetty.xml的hanler相关内容。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
<Set name="handler">
<New id="Handlers" class="org.eclipse.jetty.server.handler.HandlerCollection">
<Set name="handlers">
<Array type="org.eclipse.jetty.server.Handler">
<Item>
<New class="org.eclipse.jetty.webapp.WebAppContext">
<!-- 其余set例如contextPath省略 -->
<Set name="configurationClasses"><Ref id="plusConfig"/></Set>
</New>
</Item>
<!-- 其他handler例如RequestLogHandler省略 -->
</Array>
</Set>
</New>
</Set>
<Array id="plusConfig" type="java.lang.String">
<!-- 其他config省略,只列出问题所在 -->
<Item>com.sankuai.mms.boot.RJRAnnotationConfiguration</Item>
</Array>

HandlerCollection其实也是handler,但是其内部包含着多个其他handler的引用(数组)

1
2
3
// 最新版为AtomicReference,而服务中版本还是真数组
private volatile Handler[] _handlers;
protected final AtomicReference<Handlers> _handlers = new AtomicReference<>();

WebAppContext则是继承自ScopeHandler(如果说要和HandlerCollection同级的那就是HanlderWrapper).ScopeHandler内部只有一个handler的引用,显而易见的,为了链式调用。

代码块中只列出了WebAppContext,是因为其作为一个ContextHandler(其会创建&初始化一些servletcontext对象),内部还管理着ServletHandler等等,而ServletHandler可是真正实现了Servlet规范中的功能(Servlet, Filter, Listener)。

这块继承和实现关系不展开,有兴趣可以详细瞅下~~

好了接下来直接看代码溯源问题,看看Finalizer们是怎么来的:

  1. WebAppContext启动(由于其实现了LifeCycle,直接看start方法)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
/******** WebAppContext ********/
@Override
protected void doStart() throws Exception {
try
{
// 省略前
preConfigure();
// 这里一路向上,可以看到在ContextHandler中处理了一系列类加载器
// 最终还是调用了this.startContext();而WebAppContext中有所重载
super.doStart();
postConfigure();
// 省略后
}
catch (Throwable t) {
// 省略
}
}
@Override
protected void startContext()
throws Exception {
// 新版有所优化,先确保了 configure()成功才会接着执行。。。(其实就是加了个if)
configure();
// xml解析
_metadata.resolve(this);
// 继续start,最终启动app
super.startContext();
}

// 新版多封装了一层_configurations,先sort了一下;老版(此文服务)直接for循环调用
// preConfigure 以及 postConfigure类似
public boolean configure() throws Exception {
// return _configurations.configure(this);
for(int i = 0; i < this._configurations.length; ++i) {
this._configurations[i].preConfigure(this);
}
}

/******** Configuration interface ********/
void preConfigure(WebAppContext context) throws Exception;
void configure(WebAppContext context) throws Exception;
void postConfigure(WebAppContext context) throws Exception;
// 其他方法,例如clone省略
  1. 结果上看最终是RJRAnnotationConfiguration有问题,因其是公司内部封装的类,且核心功能在于其被继承的类,故直接看AnnotationConfiguration即可。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
/******** AnnotationConfiguration ********/
@Override
public void configure(WebAppContext context) throws Exception
{
// 省略
// 顾名思义,此处为扫所有的注解
if (!_discoverableAnnotationHandlers.isEmpty() || _classInheritanceHandler != null || !_containerInitializerAnnotationHandlers.isEmpty())
scanForAnnotations(context);
// 省略
}
/**
* Perform scanning of classes for discoverable
* annotations such as WebServlet/WebFilter/WebListener
*
* @param context the context for the scan
* @throws Exception if unable to scan
*/
protected void scanForAnnotations(WebAppContext context)
throws Exception
{
// JAVA版本相关,省略
// 日志打印,省略
//scan selected jars on the container classpath first
parseContainerPath(context, parser);
//email from Rajiv Mordani jsrs 315 7 April 2010
// If there is a <others/> then the ordering should be
// WEB-INF/classes the order of the declared elements + others.
// In case there is no others then it is
// WEB-INF/classes + order of the elements.
parseWebInfClasses(context, parser);
//scan non-excluded, non medatadata-complete jars in web-inf lib
parseWebInfLib(context, parser);
//execute scan, either effectively synchronously (1 thread only), or asynchronously (limited by number of processors available)
final Semaphore task_limit = (isUseMultiThreading(context) ? new Semaphore(ProcessorUtils.availableProcessors()) : new Semaphore(1));
final CountDownLatch latch = new CountDownLatch(_parserTasks.size());
final MultiException me = new MultiException();
for (final ParserTask p : _parserTasks)
{
task_limit.acquire();
context.getServer().getThreadPool().execute(new Runnable()
{
@Override
public void run()
{
try
{
p.call();
}
catch (Exception e)
{
me.add(e);
}
finally
{
task_limit.release();
latch.countDown();
}
}
});
}
// ...
}

根据注释可知,此方法扫描所想找到的注解是WebServlet/WebFilter/WebListener这三个注解。此外值得一提的是,scanForAnnotations中分了三个具体方法,然后均会生成parseTask,并行去解析相关jar包内容。

  1. 根据注释可知,其中parseContainerPath扫描容器目录下的jar包,parseWebInfClasses则是扫WEB-INF目录下的class文件,parseWebInfLib则是扫WEB-INF/lib下的jar包。根据dump中情况可知,主要看parseWebInfLib即可。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
 /**
* Scan jars in WEB-INF/lib. Only jars selected by MetaInfConfiguration, and that are not excluded by an ordering will be considered.
*/
public void parseWebInfLib(final WebAppContext context, final AnnotationParser parser) throws Exception
{
List<Resource> jars = context.getMetaData().getWebInfResources(context.getMetaData().isOrdered());
for (Resource r : jars)
{
//for each jar, we decide which set of annotations we need to parse for
final Set<Handler> handlers = new HashSet<Handler>();
FragmentDescriptor f = context.getMetaData().getFragmentDescriptorForJar(r);
//if its from a fragment jar that is metadata complete, we should skip scanning for @webservlet etc
// but yet we still need to do the scanning for the classes on behalf of the servletcontainerinitializers
//if a jar has no web-fragment.xml we scan it (because it is not excluded by the ordering)
//or if it has a fragment we scan it if it is not metadata complete
if (f == null || !WebDescriptor.isMetaDataComplete(f) || _classInheritanceHandler != null || !_containerInitializerAnnotationHandlers.isEmpty())
{
//register the classinheritance handler if there is one
if (_classInheritanceHandler != null)
handlers.add(_classInheritanceHandler);
//register the handlers for the @HandlesTypes values that are themselves annotations if there are any
handlers.addAll(_containerInitializerAnnotationHandlers);
//only register the discoverable annotation handlers if this fragment is not metadata complete, or has no fragment descriptor
if (f == null || !WebDescriptor.isMetaDataComplete(f))
handlers.addAll(_discoverableAnnotationHandlers);
if (_parserTasks != null)
{
// 注:都是这个task,说明内部parse逻辑还有区别
ParserTask task = new ParserTask(parser, handlers, r);
_parserTasks.add(task);
}
}
}
}

注释上看属于是既要又要还要,全都想扫。

  1. 接着看具体task内容,其核心逻辑在于AnnotationParser#parse(注:主要看扫Jar包的,例如ScanClass等方法忽略)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
/******** AnnotationParser ********/
/**
* Parse a resource
* @param handlers the handlers to look for classes in
* @param r the resource to parse
* @throws Exception if unable to parse
*/
public void parse(final Set<? extends Handler> handlers, Resource r) throws Exception
{
if (r == null)
return;
if (r.exists() && r.isDirectory())
{
parseDir(handlers, r);
return;
}
String fullname = r.toString();
if (fullname.endsWith(".jar"))
{
// 主要看这个,对应着jar包
parseJar(handlers, r);
return;
}
if (fullname.endsWith(".class"))
{
try (InputStream is = r.getInputStream())
{
scanClass(handlers, null, is);
return;
}
}
// ...
}
/**
* Parse a resource that is a jar file.
*
* @param handlers the handlers to look for classes in
* @param jarResource the jar resource to parse
* @throws Exception if unable to parse
*/
protected void parseJar(Set<? extends Handler> handlers, Resource jarResource) throws Exception
{
if (jarResource == null)
return;
if (jarResource.toString().endsWith(".jar"))
{
MultiException me = new MultiException();
try (MultiReleaseJarFile jarFile = new MultiReleaseJarFile(jarResource.getFile(), _javaPlatform, false))
{
// 封装成JarInputStream以便解压
jarFile.stream().forEach(e ->
{
try
{
// 具体处理逻辑
parseJarEntry(handlers, jarResource, e);
}
catch (Exception ex)
{
me.add(new RuntimeException("Error scanning entry " + e.getName() + " from jar " + jarResource, ex));
}
});
}
me.ifExceptionThrow();
}
}

注:JarInputStream extends ZipInputStreamZipInputStream又extends InflaterInputStreamFinalizer中有InflaterInputStream一席之地的原因找到。
而创建InflaterInputStream对象时会new出一个decompressor,那就是Inlfater :
super(new PushbackInputStream(in, 512), new Inflater(true), 512);,Finalizer中出现Inlfater众多的原因在此。

  1. 再看看我们的最终产物怎么来的,直奔AnnotationParser#parseJarEntry
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
/******** AnnotationParser ********/
/**
* Parse a single entry in a jar file
* @param handlers the handlers to look for classes in
* @param entry the entry in the potentially MultiRelease jar resource to parse
* @param jar the jar file
* @throws Exception if unable to parse
*/
protected void parseJarEntry(Set<? extends Handler> handlers, Resource jar, MultiReleaseJarFile.VersionedJarEntry entry)
throws Exception
{
if (jar == null || entry == null)
return;
//skip directories
if (entry.isDirectory())
return;

String name = entry.getName();
//check file is a valid class file name
if (isValidClassFileName(name) && isValidClassFilePath(name))
{
String shortName = StringUtil.replace(name, '/', '.').substring(0, name.length() - 6);
// 资源组装
addParsedClass(shortName, Resource.newResource("jar:" + jar.getURI() + "!/" + entry.getNameInJar()));
if (LOG.isDebugEnabled())
LOG.debug("Scanning class from jar {}!/{}", jar, entry);
try (InputStream is = entry.getInputStream())
{
// 前面有出现过。asm解析类文件
scanClass(handlers, jar, is);
}
}
}
/******** Resource ********/
public static Resource newResource(URL url)
{
return newResource(url, __defaultUseCaches);
}
/**
* Construct a resource from a url.
* @param url the url for which to make the resource
* @param useCaches true enables URLConnection caching if applicable to the type of resource
* @return a new resource from the given URL
*/
static Resource newResource(URL url, boolean useCaches)
{
if (url == null)
return null;
String urlString = url.toExternalForm();
// context启动该时扫描加过file
if (urlString.startsWith("file:"))
{
try
{
return new PathResource(url);
}
catch (Exception e)
{
if (LOG.isDebugEnabled())
LOG.warn("Bad PathResource: {}", url, e);
else
LOG.warn("Bad PathResource: {} {}", url, e.toString());
return new BadResource(url, e.toString());
}
}
// 明显走的这个分支,在前面parseJarEntry方法中又加了一次前缀
// jar包中的class文件~
else if (urlString.startsWith("jar:file:"))
{
return new JarFileResource(url, useCaches);
}
// 纯jar包
else if (urlString.startsWith("jar:"))
{
return new JarResource(url, useCaches);
}

return new URLResource(url, null, useCaches);
}

JarFileResource的出现源于此,且其中有属性private JarFile _jarFile;,故gc前有着大量JarFileFinalizer实例也破案~

JarFileResource类具体可见:https://github1s.com/eclipse/jetty.project/blob/HEAD/jetty-util/src/main/java/org/eclipse/jetty/util/resource/JarFileResource.java,https://www.eclipse.org/jetty/javadoc/jetty-9/org/eclipse/jetty/util/resource/JarFileResource.html

因果之前 - 为何需要扫注解

为什么需要扫描注解?其实通过前面代码中注解查看,可以看到扫注解主要扫的是三个,即WebServlet/WebFilter/WebListener,其实这均为Servlet3.0的注解,其是为了降低web.xml的书写复杂度而引入的(简化示例:https://stackoverflow.com/questions/9966655/servlet-3-0-webservlet-use-what-will-be-in-web-xml)。

Jetty为了支持此特性,引入了org.eclipse.jetty.annotations.AnnotationConfiguration来扫Jar包中的所有class文件。

总结因果 - 链路整体分析

Jetty为了支持Servlet3.0的注解功能,在启动时,AnnotationConfiguration会扫描WEB-INF/lib目录下的Jar的所有class文件以解析其是否由使用注解,中间产生了大量用于解压的Finalizer类实例例如Inflater,又最终生成了大量Finalizer资源实例例如JarFileResourceJarFile。因为其所产生量级大,速度快,young gc多次一直无法回收,于是大量对象直接涌入老年代,导致弹性机器“出道即巅峰”,启动后很快就需要full gc

可以预见的是,随着服务引入的jar包增多,情况会逐渐恶化。

因果之后 - 如何解决

说来蛮有意思,服务中引入了相关config以支持使用注解,但是使用的Servlet版本才在2.4,根本用不上注解,于是我爽快的删除了相关配置。

线下测试后上线,发现启动时老年代内存占用已从原来得800MB+降至不到300MB,问题成功解决。

其实第一篇Full gc和第二篇虽然是同一个服务,但是原因却天差地别。这也说明了Full gc产生的原因属实多种多样,也许是参数不合理,也许是本身业务代码问题(乱建对象等),还有可能是引入的插件有问题(一个升级,或修改一个配置可能就中招),而这其中有些是可以规避的,有些则是难以事前规避的,因此还是需要积累经验,合理利用相关内存分析工具,日志分析工具。并适时锻炼下互联网信息检索、源代码嗅觉等,这样才能更快定位并解决问题。

写在最后

不知不觉已经是到2022年的末尾了,看着朋友圈各式晒网易云年终总结,突然想起来今年还有个坑没填,想着赶紧得趁着自己还在决赛圈来补上。不曾想年久失修得记忆以及超出设想的一系列问题还是让我延迟了好久才完成。

2022在生活和工作上都有所进步,养料来源众多——书报、面谈、会议、论坛、文章、视频等等,深切体会到一味闭门造车不可取,人确实是社会关系的总和,是需要在交流中才可获得进步。

这一年发生了太多事情,让人不止一次的想到,“人类的总体命运是乐观的,而人类个体的命运是悲观的”。但是在农历年末亦临近之时,我只诚切希望大家都能远离XBB,快乐度过春节!

新的一年,在这里立个小目标,更新超过两篇…