AEM性能问题(慢速内存泄漏)org.slf4j.helpers.BasicMarker和org.slf4j.helpers.BasicMarkerFactory

16

我目前正在为客户网站(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

and
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.
  1. 希望有人能够帮我确定问题的原因,因为我有点迷失了?
  2. 有人见过这种情况吗?
  3. 如何进一步排除这个问题?
  4. 你认为 org.slf4j.helpers.BasicMarker 和 org.slf4j.helpers.BasicMarkerFactory 是我的问题根源吗?
  5. 我的日志配置是否有问题?
  6. 这是一个慢性内存泄漏还是性能调整问题(在我看来,它似乎会慢慢地出现一周左右)?

欢迎任何建议。

提前感谢。


5
首先,您在故障排除方面做得非常出色。恭喜!听起来显然存在资源泄漏的问题:1)可能是org.slf4j标记存在漏洞,2)或者“org.apache.felix.framework”未能释放资源,3)或者问题位于堆栈顶部 - Adobe Experience Manager(AEM)可能是罪魁祸首。建议:如果您的客户购买了AEM,请打开Adobe的支持票,并发布到http://felix.apache.org/和http://www.slf4j.org/。 - paulsm4
非常感谢您的迅速回复!我会在felix.apache.org上发布。我已经订阅了slf4j邮件列表,并已经发送了一条像这样的长信息,但目前还没有收到回复。关于AEM支持票据,我已经发布了一个带有Heap Dump、Thread dump和errlog的票据。他们的答案并不是很有用,因为他们根本没有提到slf4j。他们指责我的某个组件。无论如何,我再次查看了代码,但没有发现任何异常或涉及slf4j的内容。但我会再次尝试发布一张带有这条消息的支持票据。谢谢。 - nabello
很好的分析@nabello。我建议像他提到的那样,打开一个Daycare票(Adobe支持),同时在Apache Felix和SL4J中打开一个票。这很可能是一个GC错误。 - Rajesh Pantula
3
@nabello,这是Oak中的一个问题。已经开启了https://issues.apache.org/jira/browse/OAK-3476来在Oak方面修复它。 - Chetan
1
根据OAK-3476中的评论,禁用调试日志是否可以解决问题? - Bertrand Delacretaz
1
Nabello,如果你还没有这样做,请联系Adobe AEM客户支持获取最新的AEM/Oak相关热修复补丁。针对AEM6.0的Oak 1.0.23或针对AEM6.1的Oak 1.2.8包含了Chetan上面提到的OAK-3476修复。 - Andrew Khoury
1个回答

0

你是否正在使用MarkerFactory来创建你的Marker实例?

听起来很明显,你的ConcurrentHashMap持有你的Marker是不断增长的。例如,如果你每次都使用不同的名称(例如使用日期)创建一个标记。标记用于标记日志,以便您可以相应地过滤它们。您可能需要发布创建标记的代码部分。


网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接