Analyze Unclosed Sessions

Symptoms

If you experience the following conditions, the problem might be due to unclosed sessions in CRX:

• The system gets slower and slower
• From time to time the system runs out of memory (after a few hours, days, or weeks - depending on the severity)
• Older version of CRX: you have a lot of "CacheManager: resizeAll" entries in the log file (the number behind size=... is the number of caches; each sessions opens a few caches)

Cause

If an application opens CRXSessions explicitely, it is the responsibility of the developer to ensure the proper closure of these sessions. If not, such sessions will not be subject of garbage collection and thus will stay in memory, causing above listed symptoms. Each CRXSession creates and maintains its own set of caches which adds to the overall resource consumption.

Analysis

In order to pinpoint an actual problem with unclosed sessions, run following commands to determine the overall number of current CRXSessions held in memory:

• jmap -histo:live <pid> | grep CRXSessionImpl

The second column of the output is the instance count, which means that that many sessions are not closed (and actually reside in-memory). If this number is significantly higher than 100, then there is a problem with CRXSessions in your application.

To see how many CRXSession objects are held in memory including those waiting to be garbage collected, run the command below:

• jmap -histo <pid> | grep CRXSessionImpl

As with the previous command, the second column is the instance count.  This tells you how many session objects are in memory which are live or haven't been garbage collected yet.  This number, versus the previous one, can tell you if you are opening and closing too many CRX sessions in your application.

If you are running CRX2.3 or CQ5.5, then you can force a jvm full garbage collection by going to http://<host>:<port>/system/console/memoryusage and clicking the "Run Garbage Collector" button.  After doing this, you can run the above command again a few times to see how quickly the number of session objects increases.  This will give you an idea if your application is opening and closing too many sessions or if you need to tune your gc settings.  Usually if this is actually an issue you will notice large jvm garbage collection pauses and slow performance during save operations to the repository.

Note: The jmap command line application ships with the java JDK and can be found the jdk home bin directory.

Resolution

To resolve this issue, further analysis is required to find out who actually opens CRXSessions and more importantly, does not close these. Starting from 1.4.1, CRX comes with a built-in debug-mode which allows you to backtrack the defect code. What this debug-mode basically does is dump a complete stack-trace to the standard-out logfile whenever a CRXSession is openend. It also logs an entry whenever a CRXSession is closed again.

In order to enable the session debug-mode, add following JVM parameter when starting CRX:

• -Dcrx.debug.sessions=true

NOTE: Depending on the usage of the system, the log file might grow quite fast.

When using the quickstart, the -nofork option needs to be used to ensure the system property is used.

As soon as you have gathered enough stacktraces (it's easier to analyze the problem if there are at least 1000 unclosed sessions), please stop the instance and remove the JVM parameter again. The log file (system out log or error.log depending on the version used) will contains the following messages, plus stack traces:

• com.day.crx.core.CRXSessionImpl session# 193 opened

Then run the attached jar-file with following command:

• java -jar session_analyzer.jar <log_file> | sort > output.txt

This will generate a new file output.txt that contains the stack trace of unclosed sessions, sorted by stack trace content. Each stack trace is one line, and 'compressed' a bit (repeated prefixes are removed). The session id is at the end of the line.

Example:

com.day.crx.j2ee.JCRExplorerServlet.login(JCRExplorerServlet.java:521)

    ResourceServlet.spoolResource(ResourceServlet.java:148)

    java.lang.Thread.run(Thread.java:595): session# 10023

This example means session #10023 was not closed, and the stack trace included the given lines when the session was opened.

Based on this output you should be able to find the defect code location and fix the problem. In case you have found a defect in our product core code, please kindly submit a Daycare ticket along with the information gathered above.

Applies

CRX 1.3.x (please ask for a patch if you need to analyze the problem)
CRX 1.4.x (for 1.4.0 you need to install the hotfix in the attachment)
CRX 2.x