AEM 性能问题（缓慢的内存泄漏）org.slf4j.helpers.BasicMarker 和 org.slf4j.helpers.BasicMarkerFactory
Posted
技术标签:
【中文标题】AEM 性能问题（缓慢的内存泄漏）org.slf4j.helpers.BasicMarker 和 org.slf4j.helpers.BasicMarkerFactory【英文标题】：AEM performance issues (slow memory leak) org.slf4j.helpers.BasicMarker and org.slf4j.helpers.BasicMarkerFactory 【发布时间】：2015-10-10 00:33:56 【问题描述】：我目前正在为客户的网站（Java 平台）使用 Adobe Experience Manager（AEM，也称为 CQ）。它使用 OpenJDK：
java version "1.7.0_65"
OpenJDK Runtime Environment (rhel-2.5.1.2.el6_5-x86_64 u65-b17)
OpenJDK 64-Bit Server VM (build 24.65-b04, mixed mode)
它在 Rackspace 上运行，具有以下特性：
vCPU: 4
Memory: 16GB
Guest OS: Red Hat Enterprise Linux 6 (64-bit)
自从它投入生产以来，我一直在体验应用程序的性能非常缓慢。就像这样我启动应用程序，一切都很顺利，然后 7 到 10 天后 CPU 使用率飙升至 400%（约 4000 名用户/天访问该网站）。该站点变得异常缓慢，并且永远不会成为 OOM 异常。
由于我是 Java 内存管理的新手，我开始阅读它的工作原理，并找到了 jstat 和 jmap 等工具。当系统第二次不堪重负时，我得到了一个堆转储并对其进行了挖掘。
这一切似乎都在 org.slf4j.helpers.BasicMarkerFactory 和 org.slf4j.helpers.BasicMarker 中指出，因为当我用 MAT eclipse 分析它时，我发现按保留大小计算的最大保留对象是：
org.slf4j.helpers.BasicMarkerFactory @ 0x6021a4f00
Shallow Size: 16 B Retained Size: 6.8 GB
和
当我运行泄漏嫌疑人报告时，我得到以下结果：
Description
One instance of "org.slf4j.helpers.BasicMarkerFactory" loaded by "org.apache.felix.framework.BundleWiringImpl$BundleClassLoaderJava5 @ 0x60219a878" occupies 7,263,024,848 (96.71%) bytes. The memory is accumulated in one instance of "java.util.concurrent.ConcurrentHashMap$Segment[]" loaded by "<system class loader>".
Keywords
java.util.concurrent.ConcurrentHashMap$Segment[]
org.apache.felix.framework.BundleWiringImpl$BundleClassLoaderJava5 @ 0x60219a878
org.slf4j.helpers.BasicMarkerFactory
和
Shortest Paths To the Accumulation Point
Class Name Shallow Heap Retained Heap
java.util.concurrent.ConcurrentHashMap$Segment[16] @ 0x6021a4f40 80 7,263,024,784
.
... segments java.util.concurrent.ConcurrentHashMap @ 0x6021a4f10 48 7,263,024,832
.
... markerMap org.slf4j.helpers.BasicMarkerFactory @ 0x6021a4f00 16 7,263,024,848
.
... markerFactory org.slf4j.impl.StaticMarkerBinder @ 0x6021d3970 16 16
.
... SINGLETON class org.slf4j.impl.StaticMarkerBinder @ 0x6021d38f8 8 24
.
... [328] java.lang.Object[640] @ 0x6021d2ee8 2,576 9,592
.
... elementData java.util.Vector @ 0x6021d0fe0 32 9,624
.
... classes org.apache.felix.framework.BundleWiringImpl$
BundleClassLoaderJava5 @ 0x6021c32e0 96 26,888
.
... <classloader> class ch.qos.logback.classic.Logger @
0x600be4310 16 16
. .
. ...<class> ch.qos.logback.classic.Logger @ 0x600282a78 48 48
.
... <Java Local> java.lang.Thread @ 0x60077b450
pool-9-thread-1 Thread 104 3,344
.
... <class> ch.qos.logback.classic.Logger @ 0x60025b850 48 48
.
... <class> ch.qos.logback.classic.Logger @ 0x604b0a708 48 48
.
... <class> ch.qos.logback.classic.Logger @ 0x604b0a6d8 48 48
.
... <class> ch.qos.logback.classic.Logger @ 0x6049debe0 48 48
.
... <class> ch.qos.logback.classic.Logger @ 0x604535228 48 48
.
... <class> ch.qos.logback.classic.Logger @ 0x604124248 48 48
当我跑步时：
$ sudo -u aem jmap -histo PID
num #instances #bytes class name
----------------------------------------------
1: 11460084 950827248 [C
2: 10740160 257763840 java.lang.String
3: 7681495 245807840 java.util.concurrent.ConcurrentHashMap$HashEntry
4: 7563527 181524648 org.slf4j.helpers.BasicMarker
5: 217007 173568376 [I
6: 177602 158721184 [B
7: 60611 69739136 [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;
8: 1147481 69348496 [Ljava.lang.Object;
9: 1797107 43130568 org.apache.jackrabbit.oak.plugins.segment.RecordId
10: 208912 33824544 <constMethodKlass>
11: 570143 31928008 org.mozilla.javascript.ast.Name
12: 22350 27643920 <constantPoolKlass>
13: 208912 26752544 <methodKlass>
14: 821217 26278944 java.util.UUID
15: 793800 25401600 java.util.HashMap$Entry
16: 532946 21317840 org.mozilla.javascript.Node
17: 792296 19015104 java.lang.Long
18: 191294 18335600 [Ljava.util.HashMap$Entry;
19: 22350 16133328 <instanceKlassKlass>
20: 173883 15855152 [Ljava.lang.String;
21: 635690 15256560 org.apache.sling.engine.impl.request.SlingRequestProgressTracker$TrackingEntry
22: 18509 14662848 <constantPoolCacheKlass>
23: 911112 14577792 java.lang.Integer
24: 255426 14303856 org.apache.jackrabbit.oak.plugins.segment.SegmentNodeBuilder
25: 519324 12463776 java.util.ArrayList
26: 254643 12222864 org.apache.jackrabbit.oak.core.SecureNodeBuilder
27: 137703 11016240 java.lang.reflect.Method
28: 312116 9987712 org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState
29: 19236 9828448 [Lorg.apache.jackrabbit.oak.plugins.segment.SegmentId;
30: 242179 9687160 java.util.TreeMap$Entry
31: 197121 9461808 java.util.HashMap
32: 15041 9416328 <methodDataKlass>
33: 387927 9310248 org.apache.jackrabbit.oak.plugins.segment.MapRecord
34: 250049 8001568 org.apache.jackrabbit.oak.plugins.memory.MemoryNodeBuilder$UnconnectedHead
35: 248586 7954752 org.apache.jackrabbit.oak.core.MutableTree
36: 107865 7948112 [S
37: 191950 7678000 java.util.LinkedHashMap$Entry
38: 102212 6541568 org.mozilla.javascript.ast.PropertyGet
39: 37021 6515696 org.mozilla.javascript.ast.FunctionNode
40: 161905 6476200 org.mozilla.javascript.ScriptableObject$Slot
.....
8210: 1 16 org.slf4j.helpers.BasicMarkerFactory
我注意到了：
4: 7563527 181524648 org.slf4j.helpers.BasicMarker
和
8210: 1 16 org.slf4j.helpers.BasicMarkerFactory
当我查看 org.slf4j.helpers.BasicMarkerFacotry 的文档时，我看到以下内容引起了我的注意：
detachMarker
public boolean detachMarker(String name)
Description copied from interface: IMarkerFactory
Detach an existing marker.
Note that after a marker is detached, there might still be "dangling" references to the detached marker.
Specified by:
detachMarker in interface IMarkerFactory
Parameters:
name - The name of the marker to detach
Returns:
whether the marker could be detached or not
特别是：
Note that after a marker is detached, there might still be "dangling" references to the detached marker.
-
希望有人能够帮助查明我的问题的原因，因为我有点迷失在这里？
以前有人见过吗？
我该如何进一步解决此问题？
您是否同意 org.slf4j.helpers.BasicMarker 和 org.slf4j.helpers.BasicMarkerFactory 似乎是我的问题的根本原因？
我的日志记录配置有问题吗？
这是缓慢的内存泄漏还是性能调整问题（在我看来，内存泄漏似乎是在一周左右的时间内缓慢泄漏）？
欢迎任何建议。
提前致谢。
【问题讨论】：
首先，您在故障排除方面做得非常出色。恭喜！听起来显然存在资源泄漏：1）也许 org.slf4 标记有错误，2）或者“org.apache.felix.framework”未能释放资源，3）或者问题可能出在顶部堆栈 - Adobe Experience Manager (AEM) 可能是罪魁祸首。建议：向 Adobe 开一张支持票（如果您的客户购买了 AEM），然后发布到 felix.apache.org 和 slf4j.org。 非常感谢您的及时回复！我将发布到 felix.apache.org。我订阅了 slf4j 邮件列表，并且已经发送了一条像这样的长消息，但暂时没有回复。关于 AEM 支持票，我已经发布了一张带有堆转储、线程转储和错误日志的票。他们的回答并不是很有用，因为他们根本没有说过任何关于 slf4j 的事情。他们指着我的一个组件。无论如何，我再次查看了代码，但没有发现任何异常，也没有涉及 slf4j。但我会再次尝试使用此消息发布支持票。Thx @nabello 这是 Oak 中的一个问题。已打开 issues.apache.org/jira/browse/OAK-3476 将其固定在橡木一侧 根据 OAK-3476 中的 cmets，说禁用调试日志会解决问题是否正确？ Nabello，如果您还没有这样做，请联系 Adobe AEM 客户服务以获取最新的 AEM/Oak 相关修补程序。适用于 AEM6.0 的 Oak 1.0.23 或适用于 AEM6.1 的 Oak 1.2.8 包含上述 Chetan 提到的 OAK-3476 修复程序。 【参考方案1】：您是否使用MarkerFactory 创建您的Marker 实例？
听起来很明显，拿着标记的ConcurrentHashMap 在不断增长。例如，情况就是这样。如果您每次使用不同的名称创建标记（例如使用日期）。标记将标记您的日志，以便您可以相应地过滤它们。您可能希望在创建标记的位置发布代码部分。
【讨论】：
以上是关于AEM 性能问题（缓慢的内存泄漏）org.slf4j.helpers.BasicMarker 和 org.slf4j.helpers.BasicMarkerFactory的主要内容，如果未能解决你的问题，请参考以下文章
IOS性能调优系列：使用Instruments动态分析内存泄漏