Hi Nicola, This issue is most likely not related to Felix, so you'll probably get more help on AEM forums. However, I would make the following points:
A CPU spike is not usually a symptom of a memory leak, so the logger issue may be a red herring. I've noticed myself that AEM 5.6.1 may have a memory leak if you redeploy packages many times - usually it is related to the permgen memory (class storage), and happens when a package is replaced but it's classloaders and classes are not garbage collected (due to things like dangling references). But for your issue I would use top to verify the CPU spike is actually caused by AEM, and then probably run a profiler that can monitor threads to see which thread is spiking. Regards, Ben On 21 Jul 2015 8:43 am, "Nicola Abello" <[email protected]> wrote: > I am currently using the Adobe Experience Manager (AEM also known as CQ) > for a Client's site (Java platform). It uses 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) > > It is running on Rackspace with the following: > > vCPU: 4 Memory: 16GB Guest OS: Red Hat Enterprise Linux 6 (64-bit) > > Since it has been in production I have been experiencing very slow > performance on the part of the application. It goes like this I launch the > app, everything is smooth then 7 to 10 days later the CPU usage spikes to > 400% (~4000 users/day hit the site). The site becomes exceptionally slow > and never becomes an OOM exception. > > Since I am a novice at Java Memory management I started reading about how > it works and found tools like jstat and jmap. When the system was > overwhelmed the second time around, I got a heap dump and dug into it. > > It all seems to be pointing out at org.slf4j.helpers.BasicMarkerFactory and > org.slf4j.helpers.BasicMarker as when I analyze it with MAT eclipse I see > that the biggest retained object by retained size is: > > org.slf4j.helpers.BasicMarkerFactory @ 0x6021a4f00Shallow Size: 16 B > Retained Size: 6.8 GB > > and > > When I run a *Leak suspects report* I get the following result: > > DescriptionOne 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 > > and > > 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 > > Also when I run: > > $ 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 > > I noticed: > > 4: 7563527 181524648 org.slf4j.helpers.BasicMarker > > and > > 8210: 1 16 org.slf4j.helpers.BasicMarkerFactory > > When I go into the documentation of org.slf4j.helpers.BasicMarkerFacotry I > see the following that gets my attention: > > detachMarkerpublic boolean detachMarker(String name)Description copied > from interface: IMarkerFactoryDetach 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 IMarkerFactoryParameters: > name - The name of the marker to detachReturns: > whether the marker could be detached or not > > In particular: > > Note that after a marker is detached, there might still be "dangling" > references to the detached marker. > > > 1. Hopefully someone will be able to help pinpoint the cause of my > issues as I am a little lost here ? > 2. Has anyone seen this before ? > 3. How could I go about troubleshooting this issue furthermore ? > 4. Do you agree that org.slf4j.helpers.BasicMarker and > org.slf4j.helpers.BasicMarkerFactory seem to be the root cause of my > issues > ? > 5. Is my logging configuration a suspect ? > 6. Is this a slow memory leak or a performance tuning issue (in my > opinion seem like the memory leaks slowly over a week or so) ? > 7. Perhaps "org.apache.felix.framework" is failing to free resources ? > > *Any advice is welcomed.* > > Thanks in advance. >
