Intermittent JackRabbit dead lock with concurrent QueryImpl.execute() and NodeImpl.getProperty()

[sbarriba]

Hi all,

We're running JackRabbit 1.4 with Weblogic 9.1. We're seeing intermittent
issues in which the system stops responding. A closer inspection reveals
what appears to be a dead lock. The following extract from the thread dump
shows Thread 55 is waiting for thread 50 and vice versa. The stacks from the
offending threads is included below.

 

Thread 50 is executing a query and Thread 55 is getting a property.

 

Any known issues in this area with JackRabbit 1.4?

 

All help appreciated.

 

Regards,

Shaun

 

Blocked lock chains

===================

    Chain 30:

    "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

    (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for

    EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

    k@0xbd7c718 held by:

    "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1

 

 

Chain 36:

"[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k@0xbd7c718 held by:

"[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1

 

Thread Stacks

 

"[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 prio=5 alive, in native,

blocked, daemon

    -- Blocked trying to get lock:

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k@0xbd7c718[fat lock]

    at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)

    at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1630)[optimized]

    at jrockit/vm/Locks.lockFat(Locks.java:1731)[optimized]

    at

jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1277)[optimized]

    at jrockit/vm/Locks.monitorEnter(Locks.java:2389)[inlined]

    at jrockit/vm/Locks.monitorEnterForced(Locks.java:872)[optimized]

    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

    at

jrockit/vm/Locks.monitorEnterUnmatched(Ljava/lang/Object;)V(Native

Method)

    at

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k.acquire()V(Unknown Source)[optimized]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:103)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:97)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(Defau

ltISMLocking.java:65)[optimized]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(

SharedItemStateManager.java:1438)[inlined]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.getItemState(Sha

redItemStateManager.java:237)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.i

ndexIsValid(ChildAxisQuery.java:360)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.n

ext(ChildAxisQuery.java:271)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.c

alculateChildren(ChildAxisQuery.java:317)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.n

ext(ChildAxisQuery.java:268)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/DescendantSelfAxisQuery$Descenda

ntSelfAxisScorer.collectContextHits(DescendantSelfAxisQuery.java:305)[in

lined]

    at

org/apache/jackrabbit/core/query/lucene/DescendantSelfAxisQuery$Descenda

ntSelfAxisScorer.next(DescendantSelfAxisQuery.java:254)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/lucene/search/IndexSearcher.search(IndexSearcher.java:146)[in

lined]

    at

org/apache/lucene/search/IndexSearcher.search(IndexSearcher.java:124)[in

lined]

    at

org/apache/lucene/search/Hits.getMoreDocs(Hits.java:74)[optimized]

    at org/apache/lucene/search/Hits.hitDoc(Hits.java:154)[inlined]

    at org/apache/lucene/search/Hits.doc(Hits.java:103)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryHits.doc(QueryHits.java:84)

[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryResultImpl.getResults(Query

ResultImpl.java:300)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/QueryResultImpl.<init>(QueryResu

ltImpl.java:192)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryImpl.execute(QueryImpl.java

:138)[optimized]

    at

org/apache/jackrabbit/core/query/QueryImpl.execute(QueryImpl.java:176)[o

ptimized]

 

 

"[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27350 idx=0x1cc tid=26815 prio=5 alive, in native,

daemon

    at jrockit/vm/Locks.monitorExitUnmatched(Ljava/lang/Object;)V(Native

Method)

    at

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k.acquire()V(Unknown Source)[optimized]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:103)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:97)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(Defau

ltISMLocking.java:65)[optimized]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(

SharedItemStateManager.java:1438)[inlined]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.hasItemState(Sha

redItemStateManager.java:269)[optimized]

    at

org/apache/jackrabbit/core/state/LocalItemStateManager.hasItemState(Loca

lItemStateManager.java:178)[inlined]

    at

org/apache/jackrabbit/core/state/XAItemStateManager.hasItemState(XAItemS

tateManager.java:252)[optimized]

    at

org/apache/jackrabbit/core/state/SessionItemStateManager.getItemState(Se

ssionItemStateManager.java:174)[optimized]

    at

org/apache/jackrabbit/core/ItemManager.createItemInstance(ItemManager.ja

va:564)[optimized]

    at

org/apache/jackrabbit/core/ItemManager.getItem(ItemManager.java:395)[inl

ined]

    at

org/apache/jackrabbit/core/NodeImpl.getProperty(NodeImpl.java:2553)[opti

mized]

    ^-- Holding lock:

org/apache/jackrabbit/core/ItemManager@0x39227158[thin lock]

 

 

 

 

[sbarriba]

I just noticed
http://www.nabble.com/-jira--Created:-(JCR-1334)-Deadlock-with-XA-enabled-td
14997630.html. Could that be related given we've deployed JackRabbit as a
RAR module within Weblogic?

Regards,
Shaun


-----Original Message-----
From: sbarriba [mailto:sbarriba@...]
Sent: 08 May 2008 15:02
To: users@...
Subject: Intermittent JackRabbit dead lock with concurrent
QueryImpl.execute() and NodeImpl.getProperty()

Hi all,

We're running JackRabbit 1.4 with Weblogic 9.1. We're seeing intermittent
issues in which the system stops responding. A closer inspection reveals
what appears to be a dead lock. The following extract from the thread dump
shows Thread 55 is waiting for thread 50 and vice versa. The stacks from the
offending threads is included below.

 

Thread 50 is executing a query and Thread 55 is getting a property.

 

Any known issues in this area with JackRabbit 1.4?

 

All help appreciated.

 

Regards,

Shaun

 

Blocked lock chains

===================

    Chain 30:

    "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

    (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for

    EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

    k@0xbd7c718 held by:

    "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1

 

 

Chain 36:

"[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k@0xbd7c718 held by:

"[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1

 

Thread Stacks

 

"[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27345 idx=0x220 tid=26810 prio=5 alive, in native,

blocked, daemon

    -- Blocked trying to get lock:

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k@0xbd7c718[fat lock]

    at jrockit/vm/Threads.waitForUnblockSignal()V(Native Method)

    at jrockit/vm/Locks.fatLockBlockOrSpin(Locks.java:1630)[optimized]

    at jrockit/vm/Locks.lockFat(Locks.java:1731)[optimized]

    at

jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1277)[optimized]

    at jrockit/vm/Locks.monitorEnter(Locks.java:2389)[inlined]

    at jrockit/vm/Locks.monitorEnterForced(Locks.java:872)[optimized]

    at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)

    at

jrockit/vm/Locks.monitorEnterUnmatched(Ljava/lang/Object;)V(Native

Method)

    at

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k.acquire()V(Unknown Source)[optimized]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:103)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:97)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(Defau

ltISMLocking.java:65)[optimized]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(

SharedItemStateManager.java:1438)[inlined]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.getItemState(Sha

redItemStateManager.java:237)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.i

ndexIsValid(ChildAxisQuery.java:360)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.n

ext(ChildAxisQuery.java:271)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.c

alculateChildren(ChildAxisQuery.java:317)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/ChildAxisQuery$ChildAxisScorer.n

ext(ChildAxisQuery.java:268)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/DescendantSelfAxisQuery$Descenda

ntSelfAxisScorer.collectContextHits(DescendantSelfAxisQuery.java:305)[in

lined]

    at

org/apache/jackrabbit/core/query/lucene/DescendantSelfAxisQuery$Descenda

ntSelfAxisScorer.next(DescendantSelfAxisQuery.java:254)[optimized]

    at org/apache/lucene/search/Scorer.score(Scorer.java:48)[optimized]

    at

org/apache/lucene/search/IndexSearcher.search(IndexSearcher.java:146)[in

lined]

    at

org/apache/lucene/search/IndexSearcher.search(IndexSearcher.java:124)[in

lined]

    at

org/apache/lucene/search/Hits.getMoreDocs(Hits.java:74)[optimized]

    at org/apache/lucene/search/Hits.hitDoc(Hits.java:154)[inlined]

    at org/apache/lucene/search/Hits.doc(Hits.java:103)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryHits.doc(QueryHits.java:84)

[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryResultImpl.getResults(Query

ResultImpl.java:300)[optimized]

    at

org/apache/jackrabbit/core/query/lucene/QueryResultImpl.<init>(QueryResu

ltImpl.java:192)[inlined]

    at

org/apache/jackrabbit/core/query/lucene/QueryImpl.execute(QueryImpl.java

:138)[optimized]

    at

org/apache/jackrabbit/core/query/QueryImpl.execute(QueryImpl.java:176)[o

ptimized]

 

 

"[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default

(self-tuning)'" id=27350 idx=0x1cc tid=26815 prio=5 alive, in native,

daemon

    at jrockit/vm/Locks.monitorExitUnmatched(Ljava/lang/Object;)V(Native

Method)

    at

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

k.acquire()V(Unknown Source)[optimized]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:103)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(D

efaultISMLocking.java:97)[inlined]

    at

org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(Defau

ltISMLocking.java:65)[optimized]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(

SharedItemStateManager.java:1438)[inlined]

    at

org/apache/jackrabbit/core/state/SharedItemStateManager.hasItemState(Sha

redItemStateManager.java:269)[optimized]

    at

org/apache/jackrabbit/core/state/LocalItemStateManager.hasItemState(Loca

lItemStateManager.java:178)[inlined]

    at

org/apache/jackrabbit/core/state/XAItemStateManager.hasItemState(XAItemS

tateManager.java:252)[optimized]

    at

org/apache/jackrabbit/core/state/SessionItemStateManager.getItemState(Se

ssionItemStateManager.java:174)[optimized]

    at

org/apache/jackrabbit/core/ItemManager.createItemInstance(ItemManager.ja

va:564)[optimized]

    at

org/apache/jackrabbit/core/ItemManager.getItem(ItemManager.java:395)[inl

ined]

    at

org/apache/jackrabbit/core/NodeImpl.getProperty(NodeImpl.java:2553)[opti

mized]

    ^-- Holding lock:

org/apache/jackrabbit/core/ItemManager@0x39227158[thin lock]

 

 

 

 

[Marcel Reutegger]

Hi,

sbarriba wrote:
> I just noticed
> http://www.nabble.com/-jira--Created:-(JCR-1334)-Deadlock-with-XA-enabled-td
> 14997630.html. Could that be related given we've deployed JackRabbit as a
> RAR module within Weblogic?

I don't think those are related, both threads only read from the repository.

> Blocked lock chains
> ===================
>     Chain 30:
>     "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>     (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for
>     EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
>     k@0xbd7c718 held by:
>     "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1
>
> Chain 36:
> "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
> k@0xbd7c718 held by:
> "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1

this is pretty strange because both threads try to acquire a read lock, which is
guaranteed to not block, unless some other thread owns the write lock.

even more strange, the JVM claims that *both* threads hold the same monitor!

-> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '55' [...]
-> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '50' [...]

maybe a JVM upgrade will help?

regards
  marcel

[sbarriba]

Hi Marcel et al,
Just had another occurrence of the deadlock issue within JackRabbit 1.4.
Perhaps this lock chain info will enlighten someone.
I'm expecting that if I search the full thread dump we'd find 'something'
reporting that its holding lock "0x438fe98" - but nothing does? Odd.

The JVM being used is BEA JRockit(R)
R27.4.0-90-89592-1.5.0_12-20070928-1715-linux-x86_64 if that helps.

All comments welcome.
Regards,
Shaun

Blocked lock chains
===================
20+ threads all reporting waiting on Thread 21
Chain 7:
"[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default
(self-tuning)'" id=66 idx=0x104 tid=21527 waiting for
EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x
438fe98 held by:
"[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
(self-tuning)'" id=281 idx=0x1a0 tid=23875 in chain 1

Open lock chains
================
Chain 1:
"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default
(self-tuning)'" id=14 idx=0x40 tid=21444 waiting for
EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x
438fe98 held by:
"[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
(self-tuning)'" id=281 idx=0x1a0 tid=23875 (active)

Chain 3:
"ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=22 idx=0x60
tid=21452 waiting for java/lang/String@0x884a6a8 held by:
"ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=21 idx=0x5c
tid=21451 (active)


Stack for Thread 21 looks like:

[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
(self-tuning)'" id=281 idx=0x1a0 tid=23875 prio=5 alive, in native, daemon
    at jrockit/vm/Locks.monitorEnterUnmatched(Ljava/lang/Object;)V(Native
Method)
    at
EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock.ac
quire()V(Unknown Source)[optimized]
    at
org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
ltISMLocking.java:103)[inlined]
    at
org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
ltISMLocking.java:97)[inlined]
    at
org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(DefaultIS
MLocking.java:65)[optimized]
    at
org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(Shar
edItemStateManager.java:1438)[inlined]
    at
org/apache/jackrabbit/core/state/SharedItemStateManager.getItemState(SharedI
temStateManager.java:237)[optimized]
    at
org/apache/jackrabbit/core/state/LocalItemStateManager.getNodeState(LocalIte
mStateManager.java:93)[inlined]
    at
org/apache/jackrabbit/core/state/LocalItemStateManager.getItemState(LocalIte
mStateManager.java:148)[inlined]
    at
org/apache/jackrabbit/core/state/XAItemStateManager.getItemState(XAItemState
Manager.java:226)[optimized]
    ^-- Holding lock:
org/apache/jackrabbit/core/state/XAItemStateManager@0x21aa13f8[thin lock]
    at
org/apache/jackrabbit/core/state/SessionItemStateManager.getItemState(Sessio
nItemStateManager.java:175)[optimized]
    at
org/apache/jackrabbit/core/ItemManager.createItemInstance(ItemManager.java:5
64)[inlined]
    at
org/apache/jackrabbit/core/ItemManager.getItem(ItemManager.java:395)[inlined
]
    at
org/apache/jackrabbit/core/LazyItemIterator.prefetchNext(LazyItemIterator.ja
va:90)[optimized]
    ^-- Holding lock:
org/apache/jackrabbit/core/ItemManager@0x21aa19c0[recursive]
    at
org/apache/jackrabbit/core/LazyItemIterator.<init>(LazyItemIterator.java:75)
[inlined]
    at
org/apache/jackrabbit/core/ItemManager.getChildNodes(ItemManager.java:488)[i
nlined]
    at
org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2501)[optimized]
    ^-- Holding lock: org/apache/jackrabbit/core/ItemManager@0x21aa19c0[thin
lock]
    at
javax/jcr/util/TraversingItemVisitor.visit(TraversingItemVisitor.java:177)[i
nlined]
    at
org/apache/jackrabbit/core/NodeImpl.accept(NodeImpl.java:1941)[inlined]
    at
org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2787)[optimized]


-----Original Message-----
From: Marcel Reutegger [mailto:marcel.reutegger@...]
Sent: 09 May 2008 13:56
To: users@...
Subject: Re: Intermittent JackRabbit dead lock with concurrent
QueryImpl.execute() and NodeImpl.getProperty()

Hi,

sbarriba wrote:
> I just noticed
>
http://www.nabble.com/-jira--Created:-(JCR-1334)-Deadlock-with-XA-enabled-td
> 14997630.html. Could that be related given we've deployed JackRabbit as a
> RAR module within Weblogic?

I don't think those are related, both threads only read from the repository.

> Blocked lock chains
> ===================
>     Chain 30:
>     "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>     (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for
>
EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc

>     k@0xbd7c718 held by:
>     "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1
>
> Chain 36:
> "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
> k@0xbd7c718 held by:
> "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1

this is pretty strange because both threads try to acquire a read lock,
which is
guaranteed to not block, unless some other thread owns the write lock.

even more strange, the JVM claims that *both* threads hold the same monitor!

-> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '55' [...]
-> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '50' [...]

maybe a JVM upgrade will help?

regards
  marcel

[Marcel Reutegger]

Hi Shaun,

can you please provide the complete thread dump? thanks

regards
  marcel

sbarriba wrote:

> Hi Marcel et al,
> Just had another occurrence of the deadlock issue within JackRabbit 1.4.
> Perhaps this lock chain info will enlighten someone.
> I'm expecting that if I search the full thread dump we'd find 'something'
> reporting that its holding lock "0x438fe98" - but nothing does? Odd.
>
> The JVM being used is BEA JRockit(R)
> R27.4.0-90-89592-1.5.0_12-20070928-1715-linux-x86_64 if that helps.
>
> All comments welcome.
> Regards,
> Shaun
>
> Blocked lock chains
> ===================
> 20+ threads all reporting waiting on Thread 21
> Chain 7:
> "[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=66 idx=0x104 tid=21527 waiting for
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x
> 438fe98 held by:
> "[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 in chain 1
>
> Open lock chains
> ================
> Chain 1:
> "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=14 idx=0x40 tid=21444 waiting for
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x
> 438fe98 held by:
> "[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 (active)
>
> Chain 3:
> "ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=22 idx=0x60
> tid=21452 waiting for java/lang/String@0x884a6a8 held by:
> "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=21 idx=0x5c
> tid=21451 (active)
>
>
> Stack for Thread 21 looks like:
>
> [ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 prio=5 alive, in native, daemon
>     at jrockit/vm/Locks.monitorEnterUnmatched(Ljava/lang/Object;)V(Native
> Method)
>     at
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock.ac
> quire()V(Unknown Source)[optimized]
>     at
> org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
> ltISMLocking.java:103)[inlined]
>     at
> org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
> ltISMLocking.java:97)[inlined]
>     at
> org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(DefaultIS
> MLocking.java:65)[optimized]
>     at
> org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(Shar
> edItemStateManager.java:1438)[inlined]
>     at
> org/apache/jackrabbit/core/state/SharedItemStateManager.getItemState(SharedI
> temStateManager.java:237)[optimized]
>     at
> org/apache/jackrabbit/core/state/LocalItemStateManager.getNodeState(LocalIte
> mStateManager.java:93)[inlined]
>     at
> org/apache/jackrabbit/core/state/LocalItemStateManager.getItemState(LocalIte
> mStateManager.java:148)[inlined]
>     at
> org/apache/jackrabbit/core/state/XAItemStateManager.getItemState(XAItemState
> Manager.java:226)[optimized]
>     ^-- Holding lock:
> org/apache/jackrabbit/core/state/XAItemStateManager@0x21aa13f8[thin lock]
>     at
> org/apache/jackrabbit/core/state/SessionItemStateManager.getItemState(Sessio
> nItemStateManager.java:175)[optimized]
>     at
> org/apache/jackrabbit/core/ItemManager.createItemInstance(ItemManager.java:5
> 64)[inlined]
>     at
> org/apache/jackrabbit/core/ItemManager.getItem(ItemManager.java:395)[inlined
> ]
>     at
> org/apache/jackrabbit/core/LazyItemIterator.prefetchNext(LazyItemIterator.ja
> va:90)[optimized]
>     ^-- Holding lock:
> org/apache/jackrabbit/core/ItemManager@0x21aa19c0[recursive]
>     at
> org/apache/jackrabbit/core/LazyItemIterator.<init>(LazyItemIterator.java:75)
> [inlined]
>     at
> org/apache/jackrabbit/core/ItemManager.getChildNodes(ItemManager.java:488)[i
> nlined]
>     at
> org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2501)[optimized]
>     ^-- Holding lock: org/apache/jackrabbit/core/ItemManager@0x21aa19c0[thin
> lock]
>     at
> javax/jcr/util/TraversingItemVisitor.visit(TraversingItemVisitor.java:177)[i
> nlined]
>     at
> org/apache/jackrabbit/core/NodeImpl.accept(NodeImpl.java:1941)[inlined]
>     at
> org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2787)[optimized]
>
>
> -----Original Message-----
> From: Marcel Reutegger [mailto:marcel.reutegger@...]
> Sent: 09 May 2008 13:56
> To: users@...
> Subject: Re: Intermittent JackRabbit dead lock with concurrent
> QueryImpl.execute() and NodeImpl.getProperty()
>
> Hi,
>
> sbarriba wrote:
>> I just noticed
>>
> http://www.nabble.com/-jira--Created:-(JCR-1334)-Deadlock-with-XA-enabled-td
>> 14997630.html. Could that be related given we've deployed JackRabbit as a
>> RAR module within Weblogic?
>
> I don't think those are related, both threads only read from the repository.
>
>> Blocked lock chains
>> ===================
>>     Chain 30:
>>     "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>>     (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for
>>
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
>>     k@0xbd7c718 held by:
>>     "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1
>>
>> Chain 36:
>> "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for
>> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
>> k@0xbd7c718 held by:
>> "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1
>
> this is pretty strange because both threads try to acquire a read lock,
> which is
> guaranteed to not block, unless some other thread owns the write lock.
>
> even more strange, the JVM claims that *both* threads hold the same monitor!
>
> -> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '55' [...]
> -> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '50' [...]
>
> maybe a JVM upgrade will help?
>
> regards
>   marcel
>
>
>

[sbarriba]

Hi Marcel et al,
As follow up to this issue.
Where a server is under high load repeatedly taking thread dumps
occasionally shows threads waiting on locks that no one holds. We think
that's simply because as the number of threads increase, the level of
concurrency increases and the OS is context switching, there is a period of
time between one thread releasing and another taking the lock that the dump
implies no one is holding it.

Regards,
Shaun

-----Original Message-----
From: Marcel Reutegger [mailto:marcel.reutegger@...]
Sent: 19 May 2008 09:59
To: users@...
Subject: Re: Intermittent JackRabbit dead lock with concurrent
QueryImpl.execute() and NodeImpl.getProperty()

Hi Shaun,

can you please provide the complete thread dump? thanks

regards
  marcel

sbarriba wrote:

> Hi Marcel et al,
> Just had another occurrence of the deadlock issue within JackRabbit 1.4.
> Perhaps this lock chain info will enlighten someone.
> I'm expecting that if I search the full thread dump we'd find 'something'
> reporting that its holding lock "0x438fe98" - but nothing does? Odd.
>
> The JVM being used is BEA JRockit(R)
> R27.4.0-90-89592-1.5.0_12-20070928-1715-linux-x86_64 if that helps.
>
> All comments welcome.
> Regards,
> Shaun
>
> Blocked lock chains
> ===================
> 20+ threads all reporting waiting on Thread 21
> Chain 7:
> "[ACTIVE] ExecuteThread: '3' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=66 idx=0x104 tid=21527 waiting for
>

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x

> 438fe98 held by:
> "[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 in chain 1
>
> Open lock chains
> ================
> Chain 1:
> "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=14 idx=0x40 tid=21444 waiting for
>

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock@0x

> 438fe98 held by:
> "[ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 (active)
>
> Chain 3:
> "ExecuteThread: '1' for queue: 'weblogic.socket.Muxer'" id=22 idx=0x60
> tid=21452 waiting for java/lang/String@0x884a6a8 held by:
> "ExecuteThread: '0' for queue: 'weblogic.socket.Muxer'" id=21 idx=0x5c
> tid=21451 (active)
>
>
> Stack for Thread 21 looks like:
>
> [ACTIVE] ExecuteThread: '21' for queue: 'weblogic.kernel.Default
> (self-tuning)'" id=281 idx=0x1a0 tid=23875 prio=5 alive, in native, daemon
>     at jrockit/vm/Locks.monitorEnterUnmatched(Ljava/lang/Object;)V(Native
> Method)
>     at
>

EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLock.ac
> quire()V(Unknown Source)[optimized]
>     at
>
org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
> ltISMLocking.java:103)[inlined]
>     at
>
org/apache/jackrabbit/core/state/DefaultISMLocking$ReadLockImpl.<init>(Defau
> ltISMLocking.java:97)[inlined]
>     at
>
org/apache/jackrabbit/core/state/DefaultISMLocking.acquireReadLock(DefaultIS
> MLocking.java:65)[optimized]
>     at
>
org/apache/jackrabbit/core/state/SharedItemStateManager.acquireReadLock(Shar
> edItemStateManager.java:1438)[inlined]
>     at
>
org/apache/jackrabbit/core/state/SharedItemStateManager.getItemState(SharedI
> temStateManager.java:237)[optimized]
>     at
>
org/apache/jackrabbit/core/state/LocalItemStateManager.getNodeState(LocalIte
> mStateManager.java:93)[inlined]
>     at
>
org/apache/jackrabbit/core/state/LocalItemStateManager.getItemState(LocalIte
> mStateManager.java:148)[inlined]
>     at
>
org/apache/jackrabbit/core/state/XAItemStateManager.getItemState(XAItemState
> Manager.java:226)[optimized]
>     ^-- Holding lock:
> org/apache/jackrabbit/core/state/XAItemStateManager@0x21aa13f8[thin lock]
>     at
>
org/apache/jackrabbit/core/state/SessionItemStateManager.getItemState(Sessio
> nItemStateManager.java:175)[optimized]
>     at
>
org/apache/jackrabbit/core/ItemManager.createItemInstance(ItemManager.java:5
> 64)[inlined]
>     at
>
org/apache/jackrabbit/core/ItemManager.getItem(ItemManager.java:395)[inlined
> ]
>     at
>
org/apache/jackrabbit/core/LazyItemIterator.prefetchNext(LazyItemIterator.ja
> va:90)[optimized]
>     ^-- Holding lock:
> org/apache/jackrabbit/core/ItemManager@0x21aa19c0[recursive]
>     at
>
org/apache/jackrabbit/core/LazyItemIterator.<init>(LazyItemIterator.java:75)
> [inlined]
>     at
>
org/apache/jackrabbit/core/ItemManager.getChildNodes(ItemManager.java:488)[i
> nlined]
>     at
>
org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2501)[optimized]
>     ^-- Holding lock:
org/apache/jackrabbit/core/ItemManager@0x21aa19c0[thin
> lock]
>     at
>
javax/jcr/util/TraversingItemVisitor.visit(TraversingItemVisitor.java:177)[i
> nlined]
>     at
> org/apache/jackrabbit/core/NodeImpl.accept(NodeImpl.java:1941)[inlined]
>     at
>
org/apache/jackrabbit/core/NodeImpl.getNodes(NodeImpl.java:2787)[optimized]

>
>
> -----Original Message-----
> From: Marcel Reutegger [mailto:marcel.reutegger@...]
> Sent: 09 May 2008 13:56
> To: users@...
> Subject: Re: Intermittent JackRabbit dead lock with concurrent
> QueryImpl.execute() and NodeImpl.getProperty()
>
> Hi,
>
> sbarriba wrote:
>> I just noticed
>>
>

http://www.nabble.com/-jira--Created:-(JCR-1334)-Deadlock-with-XA-enabled-td
>> 14997630.html. Could that be related given we've deployed JackRabbit as a
>> RAR module within Weblogic?
>
> I don't think those are related, both threads only read from the
repository.

>
>> Blocked lock chains
>> ===================
>>     Chain 30:
>>     "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>>     (self-tuning)'" id=27350 idx=0x1cc tid=26815 waiting for
>>
> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
>>     k@0xbd7c718 held by:
>>     "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27345 idx=0x220 tid=26810 in chain 1
>>
>> Chain 36:
>> "[ACTIVE] ExecuteThread: '50' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27345 idx=0x220 tid=26810 waiting for
>> EDU/oswego/cs/dl/util/concurrent/WriterPreferenceReadWriteLock$ReaderLoc
>> k@0xbd7c718 held by:
>> "[ACTIVE] ExecuteThread: '55' for queue: 'weblogic.kernel.Default
>> (self-tuning)'" id=27350 idx=0x1cc tid=26815 in chain 1
>
> this is pretty strange because both threads try to acquire a read lock,
> which is
> guaranteed to not block, unless some other thread owns the write lock.
>
> even more strange, the JVM claims that *both* threads hold the same

monitor!

>
> -> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '55' [...]
> -> ReaderLock@0xbd7c718 held by: "[ACTIVE] ExecuteThread: '50' [...]
>
> maybe a JVM upgrade will help?
>
> regards
>   marcel
>
>
>