AEM 6.3sp1, Jdk8u121, multiple 'avoid concurrent use of a session'

[bobkranson]

Has anyone noticed a fair number of WARN messages in AEM 6.3sp1?  This is just out-of-the-box with some JVM_OPTS configuration and no custom anything loaded to the framework:

"org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform refresh while thread Apache Sling Resource Provider Change Notifier was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session."

My first reaction would be to test with a new JDK version but in my case that's not a preferred approach or solution.  In consideration of Jorg's past suggestion, I will test it again with no JVM parameters added but I would still be interested if others in the community are seeing these warning and whether someone might have found a little tweak to solve them.

[bobkranson]

Still the messages are there with default JVM_OPTS.....

[kautuk_sahni]

Reference Blog :- AEM scaling patterns: Avoid shared sessions | Things on a content management system

Jörg Hoh Need your help here!!

~kautuk

[Jörg_Hoh]

Hi,

This has nothing to do with JVM parameters, but is rather a warning originating in the product. Without the full error message (which should include a stack trace) it is not possible to further diagnose it.

Jörg

[bobkranson]

No stack trace or exception.  It is queued and blocked.  It occurs in too many places to send a simple section of the error.log.  Want to avoid lost transactions or repository corruptions.

I will venture to increase logging on that package/class (org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate) to get more detail around the source of the message.

Can you please suggest most helpful package(s) and level(s) specification for the logging?

Bob

[Jörg_Hoh]

Hi,

there must be more definitly more information in this warning. Please post the complete line of the exception (there is a thread name in it, which is absolutly important!) and the following lines.

If you have 6.3 SP1, you should have Oak 1.6.3, so you can check the code here:

jackrabbit-oak/SessionDelegate.java at jackrabbit-oak-1.6.3 · apache/jackrabbit-oak · GitHub

I don't think that setting this log to DEBUG will help you; you just might get more information about threads reading concurrently from the very same session.

[bobkranson]

Here's the full lines from the 'find all: Blocked' taking the error log into Notepad++.  I'll take a look at the GitHub code for a little more info in the meantime....(thank you)

Line 1493: 03.11.2017 10:45:46.998 *WARN* [Apache Sling Resource Provider Change Notifier] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform refresh while thread Apache Sling Resource Provider Change Notifier was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

Line 1504: 03.11.2017 10:45:47.020 *WARN* [Apache Sling Resource Provider Change Notifier] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getItemOrNull while thread Apache Sling Resource Provider Change Notifier was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

Line 1506: 03.11.2017 10:45:47.022 *WARN* [Apache Sling Resource Provider Change Notifier] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform refresh while thread Apache Sling Resource Provider Change Notifier was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

[Jörg_Hoh]

Ok, that's interesting:

03.11.2017 10:45:46.998 *WARN* [Apache Sling Resource Provider Change Notifier] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform refresh while thread Apache Sling Resource Provider Change Notifier was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

The "Apache Sling Resource Provider Change Notifier" thread is complaining that a "Apache Sling Resource Provider Change Notifier" is writing to the very same session. The thread names look pretty much the same ...

So either there are 2 threads having the same name (can you check that with a threaddump) or the code has a bug. Can you check the threaddump?

[bobkranson]

Hmmm...doesn't look like duplicate thread name.  Here's what I did and the result.  More on Monday....

Download thread dump gz
Extract file
Open in Notepad++
Find first occurrence of <EndOfDump>
Delete everything after that.
Do a regular expression find for ^"
Copy find result (all thread names for single dump that line begins with ")
Paste into Excel (116 lines)
Text to columns, delimiter :
Text to columns, delimter " <space>
Sort the column C to group thread names with like names

Results in this list:
Activator#1
Adobe Granite ChainReplicationService Processor
Adobe Granite Maintenance Scheduler Update Task
Apache Sling Control Listener@/127.0.0.1:36032
Apache Sling Job Topology Listener Thread
Apache Sling Resource Resolver Finalizer Thread
Apache Sling Scheduled Job Handler Thread
ApacheSlingdefault_QuartzSchedulerThread
ApacheSlingoak_QuartzSchedulerThread
Attach Listener
Cluster Master Observer
CM Configuration Updater
CM Event Dispatcher
CommitStats
Coordination Timer
DestroyJavaVM
discovery.connectors.common.runner.fc587403-6ae7-4483-8244-58ef8d765838.connectorPinger
discovery.connectors.common.runner.fc587403-6ae7-4483-8244-58ef8d765838.discoveryLiteCheck
Discovery-AsyncEventSender
EMailNotificationService-Processor
FelixDispatchQueue
FelixFrameworkWiring
FelixStartLevel
FileStore background tasks
Finalizer
FlushService-Worker-0
FlushService-Worker-1
FlushService-Worker-2
FlushService-Worker-3
FlushService-Worker-4
Java2D Disposer
JcrInstaller.1
JMX OSGi Bundle State Event Dispatcher
JMX OSGi Service State Event Dispatcher
logback-1
logback-2
LogEntry Dispatcher
MemMgr-1170
oak-repository-executor-1
org.eclipse.jetty.server.session.HashSessionManager@5c848342Timer
OsgiInstallerImpl
Payload Move Listener Thread
PayloadMap Cache Updater Thread
pool-276-thread-1
pool-49-thread-1
pool-66-thread-1
pool-69-thread-1
process reaper
qtp2038798393-152-selector-ServerConnectorManager@6ef377ce/0
qtp2038798393-153-selector-ServerConnectorManager@6ef377ce/1
qtp2038798393-154-acceptor-0@1945110-ServerConnector@680ce62a{HTTP/1.1}{0.0.0.0:4503}
qtp2038798393-155
qtp2038798393-156
qtp2038798393-157
qtp2038798393-158
qtp2038798393-159
Reference Handler
ReplicateOnModification Processor
RetryTimer
Scene7AssetDeletionListener[1274]
Scheduled page event service
SCR Component Actor
Shell Script Executor Thread for cpu.sh
Shell Script Executor Thread for diskusage.sh
Signal Dispatcher
sling-default-11
sling-default-12
sling-default-13
sling-default-14-com.adobe.granite.threaddump.impl.ThreadDumpCollector
sling-default-15
sling-event-processing-pool-1
sling-oak-2
sling-oak-observation-1
sling-oak-observation-10
sling-oak-observation-11
sling-oak-observation-12
sling-oak-observation-13
sling-oak-observation-14
sling-oak-observation-15
sling-oak-observation-16
sling-oak-observation-17
sling-oak-observation-18
sling-oak-observation-19
sling-oak-observation-2
sling-oak-observation-20
sling-oak-observation-3
sling-oak-observation-4
sling-oak-observation-5
sling-oak-observation-6
sling-oak-observation-7
sling-oak-observation-8
sling-oak-observation-9
Statistics write back
TaskEMailNotificationService-Processor
Thread-10
Thread-11
Thread-13
Thread-14
Thread-15
Thread-16
Thread-17
Thread-18
Thread-19
Thread-46
Thread-47
Thread-50
Thread-51
Thread-62
Thread-71
Thread-72
Thread-9
Thread-916
Timer-0
Timer-1
Timer-2
Workflow Starter Thread

End of List of Thread Names

[Jörg_Hoh · Accepted solution]

Hi,

ok, that was expected right now. The code creates threads which send send events, but all threads have the same name "Apache Sling Resource Provider Change Notifier". And obviously one the activities of these threads is using a service, which has a shared session. And at one point 2 of these threads call a method (the same?) of this service which causes this message.

Please raise a Daycare ticket and attach the complete logs. Hopefully it gets clearer which service and which session is affected by it.

[bobkranson]

Thank you!  I will follow-up with Support later in the week.