Analyze event handler problems

ค้นหา

อัปเดตครั้งล่าสุดเมื่อ 21 ธ.ค. 2021 | และยังใช้กับ CQ

Issue

You see the following error in the logs/crx/error.log file:

*WARN * ObservationDispatcher: More than 200000 events in the queue

Or, the system is slow during data import.

Solution

To analyze the issue, do the following:

Create an EventConsumer debug that gives you timing of the execution of each JCR event listener.
Reproduce the issue and take thread dumps and run the profiler to collect details of what code or content is causing the issue.
Modify your code to fix the problem, clean up the content that is causing the problem, or contact AEM (CQ) support if the problem seems to be related to product code.

1. Create an EventConsumer debug log

In CQ5.4/CRX2.2 or earlier:

Stop CQ.
Set the following log level in the crx-quickstart/server/runtime/0/_crx/WEB-INF/log4j.xml <logger name="org.apache.jackrabbit.core.observation.EventConsumer">
<level value="debug" />
</logger>
Start CQ.
Now, in logs/crx/error.log you see debug log messages from org.apache.jackrabbit.core.observation.EventConsumer showing the execution time for each event handler.

In CQ5.5/CRX2.3 or later (including AEM versions):

Go to http://host:port/system/console/configMgr and log in as admin.
Find the Apache Sling Logging Logger factory and create an instance by clicking the + button on the right of the factory configuration. This step creates a new logging logger.
Set the configuration with these settings:
Log Level: DEBUG
Log File Path: logs/eventconsumer.log
Categories: org.apache.jackrabbit.core.observation.EventConsumer
Now in logs/eventconsumer.log you see debug log messages from org.apache.jackrabbit.core.observation.EventConsumer showing the execution time for each event handler.

2. Reproduce the issue

Now that you have a debug log file, reproduce the issue by retrying whatever activity seemed to cause the events to pile up. Now take thread dumps and run the CPU profiler to help identify what is causing the slowness.

3. Change the code to fix the problem

You have collected DEBUG logs, thread dumps, and CPU profiler output so you now have enough information to conclude a root cause. See [2] below for sample log messages showing a long running JCR EventListener / EventConsumer.

Based on the findings, you could see one of the following:

A bug in a custom JCR EventListener - to resolve the problem, optimize your code.
A large accumulation of content causing a custom or out of the box JCR EventListener to run slow.
To fix the issue, delete the related content that you no longer need:
1. Go to CRX Explorer http://host:port/crx/explorer/index.jsp (/crx/index.jsp in CQ5.4 and older versions)
2. Open "Content Explorer" and browse to the content path you would like to clean up.
3. Right click the node at the top of the tree you want to delete and select "Delete Recursively"
4. Disable preliminary scan and run
An issue with an out of the box JCR Event Listener - contact AEM (CQ) support for assistance.

[1] Related error message

07.04.2010 11:05:24 *WARN * ObservationDispatcher: More than 200000 events in the queue (ObservationDispatcher.java, line 228)
java.lang.Exception: Stack Trace
at org.apache.jackrabbit.core.observation.ObservationDispatcher.dispatchEvents(ObservationDispatcher.java:228)
at org.apache.jackrabbit.core.observation.EventStateCollection.dispatch(EventStateCollection.java:465)
at org.apache.jackrabbit.core.state.SharedItemStateManager$Update.end(SharedItemStateManager.java:763)
at org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:1109)
at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:351)
at org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:354)
at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:326)
at org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:331)
at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:1124)
at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:919)
at com.day.jcr.vault.fs.io.AutoSave.save(AutoSave.java:114)
at com.day.jcr.vault.fs.io.Importer.commit(Importer.java:677)

[2] Sample EventConsumer DEBUG log messages

25.11.2013 00:00:11.115 *DEBUG* [ObservationManager] org.apache.jackrabbit.core.observation.EventConsumer listener com.day.cq.rewriter.linkchecker.impl.LinkInfoStorageImpl processed events in 15250 ms.
25.11.2013 00:01:26.859 *DEBUG* [ObservationManager] org.apache.jackrabbit.core.observation.EventConsumer listener com.day.cq.rewriter.linkchecker.impl.LinkInfoStorageImpl processed events in 74077 ms.
25.11.2013 00:02:30.569 *DEBUG* [ObservationManager] org.apache.jackrabbit.core.observation.EventConsumer listener com.day.cq.rewriter.linkchecker.impl.LinkInfoStorageImpl processed events in 49786 ms.

Additional information

The error is usually due to something wrong with the JCR event listeners. A particular JCR event listener could be handling events incorrectly or processing them too slow for some reason.

See here for some background information on JCR Event Listeners.