Return-Path: 
 <dev-return-26536-apmail-jackrabbit-dev-archive=jackrabbit.apache.org@jackrabbit.apache.org>
Delivered-To: apmail-jackrabbit-dev-archive@www.apache.org
Received: (qmail 36568 invoked from network); 14 Dec 2009 13:11:44 -0000
Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3)
  by minotaur.apache.org with SMTP; 14 Dec 2009 13:11:44 -0000
Received: (qmail 25715 invoked by uid 500); 14 Dec 2009 13:11:43 -0000
Delivered-To: apmail-jackrabbit-dev-archive@jackrabbit.apache.org
Received: (qmail 25632 invoked by uid 500); 14 Dec 2009 13:11:43 -0000
Mailing-List: contact dev-help@jackrabbit.apache.org; run by ezmlm
Precedence: bulk
List-Help: <mailto:dev-help@jackrabbit.apache.org>
List-Unsubscribe: <mailto:dev-unsubscribe@jackrabbit.apache.org>
List-Post: <mailto:dev@jackrabbit.apache.org>
List-Id: <dev.jackrabbit.apache.org>
Reply-To: dev@jackrabbit.apache.org
Delivered-To: mailing list dev@jackrabbit.apache.org
Received: (qmail 25350 invoked by uid 99); 14 Dec 2009 13:11:42 -0000
Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230)
    by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 14 Dec 2009 13:11:42 +0000
X-ASF-Spam-Status: No, hits=-2000.0 required=10.0
	tests=ALL_TRUSTED
X-Spam-Check-By: apache.org
Received: from [140.211.11.140] (HELO brutus.apache.org) (140.211.11.140)
    by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 14 Dec 2009 13:11:40 +0000
Received: from brutus (localhost [127.0.0.1])
	by brutus.apache.org (Postfix) with ESMTP id 3BB0529A001A
	for <dev@jackrabbit.apache.org>; Mon, 14 Dec 2009 05:11:18 -0800 (PST)
Message-ID: <1248978292.1260796278242.JavaMail.jira@brutus>
Date: Mon, 14 Dec 2009 13:11:18 +0000 (UTC)
From: "Andrey Adamovich (JIRA)" <jira@apache.org>
To: dev@jackrabbit.apache.org
Subject: [jira] Updated: (JCR-1846) Jackrabbit thread contention issue due
 to fat lock
In-Reply-To: <239294011.1225661204350.JavaMail.jira@brutus>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394
X-Virus-Checked: Checked by ClamAV on apache.org


     [ https://issues.apache.org/jira/browse/JCR-1846?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Andrey Adamovich updated JCR-1846:
----------------------------------

    Attachment: jr_dump.txt

This dump shows that many threads are trying to get lock from AbstractJournal and that none is holding that lock. 

> Jackrabbit thread contention issue due to fat lock
> --------------------------------------------------
>
>                 Key: JCR-1846
>                 URL: https://issues.apache.org/jira/browse/JCR-1846
>             Project: Jackrabbit Content Repository
>          Issue Type: Bug
>          Components: jackrabbit-core
>    Affects Versions: core 1.4.5, core 1.4.6, 1.5.0, 1.5.2
>         Environment: jrockit-R27.5.0-jdk1.5.0_14
> weblogic 9.2.3
> spring 2.5.5
> oracle-jdbc-10.2.0.2.0
>            Reporter: Trang Nguyen
>             Fix For: core 1.4.7, 1.5.2
>
>         Attachments: JCR-1846.patch, jr_dump.txt
>
>
> Hello,
> We are running jackrabbit 1.4.5 using a persistent file data store within a weblogic container and encountering a variety of thread locking issues. To get around the problem, we are forced synchronize thread access to the JCR repository or reduce thread worker count to 1 which has a heavy performance impact on our application. I'm not exactly sure what the problem is and was wondering someone is looking into this issue and if there is a workaround/fix planned?
> <Oct 30, 2008 10:45:32 AM PDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "1,863" seconds working on the request "weblogic.work.j2ee.J2EEWorkManager$WorkWithListener@2117cc9", which is more than the configured time (StuckThreadMaxTime) of "1,800" seconds. Stack trace:
> Thread-94 "[STUCK] ExecuteThread: '5' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, waiting, priority=1, DAEMON> {
>     -- Waiting for notification on: EDU.oswego.cs.dl.util.concurrent.WriterPreferenceReadWriteLock$WriterLock@152c384[fat lock]
>     java.lang.Object.wait(Object.java:???)
>     java.lang.Object.wait(Object.java:474)
>     EDU.oswego.cs.dl.util.concurrent.WriterPreferenceReadWriteLock$WriterLock.acquire(Unknown Source)
>     org.apache.jackrabbit.core.journal.AbstractJournal.lockAndSync(AbstractJournal.java:235)
>     org.apache.jackrabbit.core.journal.DefaultRecordProducer.append(DefaultRecordProducer.java:49)
> }
> >
> <Oct 30, 2008 10:45:32 AM PDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "1,916" seconds working on the request "weblogic.work.j2ee.J2EEWorkManager$WorkWithListener@227b6d4", which is more than the configured time (StuckThreadMaxTime) of "1,800" seconds. Stack trace:
> Thread-25 "[STUCK] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, waiting, priority=1, DAEMON> {
>     -- Waiting for notification on: EDU.oswego.cs.dl.util.concurrent.LinkedNode@42d58e0[fat lock]
>     java.lang.Object.wait(Object.java:???)
>     java.lang.Object.wait(Object.java:474)
>     EDU.oswego.cs.dl.util.concurrent.SynchronousChannel.put(Unknown Source)
>     EDU.oswego.cs.dl.util.concurrent.PooledExecutor$WaitWhenBlocked.blockedAction(Unknown Source)
>     EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(Unknown Source)
> ...
>     org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:334)
>     org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:307)
>     org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:317)
>     org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:1072)
>     ^-- Holding lock: org.apache.jackrabbit.core.query.lucene.VolatileIndex@3eb0f41[thin lock]
>     org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:895)
>     org.apache.jackrabbit.jca.JCASessionHandle.save(JCASessionHandle.java:178)
>     com.qpass.inventory.ingestion.IngestionServiceImpl$1.doInJCR(IngestionServiceImpl.java:124)
>     com.qpass.inventory.model.JCRTemplate.execute(JCRTemplate.java:17)
>     com.qpass.inventory.ingestion.IngestionServiceImpl.ingestProduct(IngestionServiceImpl.java:93)
>     com.qpass.inventory.ingestion.bulk.AbstractBulkIngester.ingestProduct(AbstractBulkIngester.java:42)
>     com.qpass.inventory.ingestion.bulk.ZipFileBulkIngester.processFile(ZipFileBulkIngester.java:35)
>     com.qpass.inventory.ingestion.bulk.IngestionWorker.processFile(IngestionWorker.java:26)
>     com.qpass.inventory.ingestion.bulk.IngestionWorker$1.run(IngestionWorker.java:64)
>     org.springframework.scheduling.commonj.DelegatingWork.run(DelegatingWork.java:61)
>     weblogic.work.j2ee.J2EEWorkManager$WorkWithListener.run(J2EEWorkManager.java:245)
>     weblogic.work.ExecuteThread.execute(ExecuteThread.java:206)
>     weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
> }
> >
> <Oct 30, 2008 10:45:32 AM PDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "1,891" seconds working on the request "weblogic.work.j2ee.J2EEWorkManager$WorkWithListener@2117c83", which is more than the configured time (StuckThreadMaxTime) of "1,800" seconds. Stack trace:
> Thread-24 "[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, waiting, priority=1, DAEMON> {
>     -- Waiting for notification on: EDU.oswego.cs.dl.util.concurrent.WriterPreferenceReadWriteLock$WriterLock@152c384[fat lock]
>     java.lang.Object.wait(Object.java:???)
>     java.lang.Object.wait(Object.java:474)
>     EDU.oswego.cs.dl.util.concurrent.WriterPreferenceReadWriteLock$WriterLock.acquire(Unknown Source)
>     org.apache.jackrabbit.core.journal.AbstractJournal.lockAndSync(AbstractJournal.java:235)
>     org.apache.jackrabbit.core.journal.DefaultRecordProducer.append(DefaultRecordProducer.java:49)
>     org.apache.jackrabbit.core.cluster.ClusterNode$WorkspaceUpdateChannel.updateCreated(ClusterNode.java:556)
> ...
> <Oct 30, 2008 11:21:30 AM PDT> <Warning> <netuix> <BEA-423420> <Redirect is executed in begin or refresh action. Redirect url is /console/console.portal?_nfpb=true&_pageLabel=HomePage1.>
> <Oct 30, 2008 11:44:32 AM PDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "1,803" seconds working on the request "Http Request: /inventory/rpc/searchService", which is more than the configured time (StuckThreadMaxTime) of "1,800" seconds. Stack trace:
> Thread-51 "[STUCK] ExecuteThread: '4' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, waiting, priority=1, DAEMON> {
>     -- Waiting for notification on: java.lang.Object@1569e04[fat lock]
>     java.lang.Object.wait(Object.java:???)
>     java.lang.Object.wait(Object.java:474)
>     org.apache.jackrabbit.core.query.lucene.MultiIndex.getIndexReader(MultiIndex.java:694)
>     org.apache.jackrabbit.core.query.lucene.SearchIndex.getIndexReader(SearchIndex.java:825)
>     org.apache.jackrabbit.core.query.lucene.SearchIndex.executeQuery(SearchIndex.java:682)
>     org.apache.jackrabbit.core.query.lucene.QueryResultImpl.executeQuery(QueryResultImpl.java:242)
>     org.apache.jackrabbit.core.query.lucene.QueryResultImpl.getResults(QueryResultImpl.java:271)
>     org.apache.jackrabbit.core.query.lucene.QueryResultImpl.<init>(QueryResultImpl.java:177)
>     org.apache.jackrabbit.core.query.lucene.QueryImpl.execute(QueryImpl.java:105)
>     org.apache.jackrabbit.core.query.QueryImpl.execute(QueryImpl.java:174)
>     com.qpass.inventory.service.QueryProfiler.execute(QueryProfiler.java:20)
>     com.qpass.inventory.service.SearchServiceImpl$1.doInJCR(SearchServiceImpl.java:59)
>     com.qpass.inventory.model.JCRTemplate.execute(JCRTemplate.java:17)
>     com.qpass.inventory.service.SearchServiceImpl.doSearch(SearchServiceImpl.java:54)
>     com.qpass.inventory.ui.impl.SearchUIServiceImpl.search(SearchUIServiceImpl.java:48)
>     sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:???)
>     sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:27)
>     sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>     java.lang.reflect.Method.invoke(Method.java:570)
>     org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
>     org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
>     org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:148)
>     org.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:62)
>     org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:148)
>     org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:151)
>     $Proxy74.search(Unknown Source)
>     sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:???)
>     sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:27)
>     sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>     java.lang.reflect.Method.invoke(Method.java:570)
>     org.gwtwidgets.server.spring.GWTRPCServiceExporter.invokeMethodOnService(GWTRPCServiceExporter.java:157)
>     org.gwtwidgets.server.spring.GWTRPCServiceExporter.processCall(GWTRPCServiceExporter.java:295)
>     com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:173)
>     org.gwtwidgets.server.spring.GWTRPCServiceExporter.handleRequest(GWTRPCServiceExporter.java:361)
>     com.qpass.base.ui.security.GWTServiceExporter.handleRequest(GWTServiceExporter.java:45)
>     org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter.handle(HttpRequestHandlerAdapter.java:49)
>     org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:831)
>     org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:781)
>     org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:567)
>     org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:511)
>     javax.servlet.http.HttpServlet.service(HttpServlet.java:736)
>     javax.servlet.http.HttpServlet.service(HttpServlet.java:851)
>     weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:224)
>     weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:108)
>     weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:198)
>     weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:26)
>     weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:41)
>     org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:259)
>     org.acegisecurity.intercept.web.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:93)
>     org.acegisecurity.intercept.web.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:71)
>     org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:259)
>     com.qpass.usersecurity.auth.UpdatePermissionsOnContextChangeFilter.doFilter(UpdatePermissionsOnContextChangeFilter.java:44)
>     org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:259)
>     org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:191)
>     org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:259)
>     org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:195)
>     org.acegisecurity.util.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:259)
>     org.acegisecurity.util.FilterChainProxy.doFilter(FilterChainProxy.java:122)
>     org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:236)
>     org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:154)
>     weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:41)
>     com.qpass.base.applicationcontext.RequestContextFilter.doFilter(RequestContextFilter.java:103)
>     org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:236)
>     org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:154)
>     weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:41)
>     org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:90)
>     org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:61)
>     weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:41)
>     weblogic.servlet.internal.RequestEventsFilter.doFilter(RequestEventsFilter.java:24)
>     weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:41)
>     weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3214)
>     weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:308)
>     weblogic.security.service.SecurityManager.runAs(SecurityManager.java:117)
>     weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:1946)
>     weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:1868)
>     weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1331)
>     weblogic.work.ExecuteThread.execute(ExecuteThread.java:206)
>     weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
> }
> <Oct 2, 2008 2:09:36 PM PDT> <Error> <WebLogicServer> <BEA-000337> <[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)' has been busy for "696" seconds working on the request "weblogic.work.j2ee.J2EEWorkManager$WorkWithListener@863e564", which is more than the configured time (StuckThreadMaxTime) of "600" seconds. Stack trace:
> Thread-21 "[STUCK] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" <alive, in native, suspended, priority=1, DAEMON> {
>     java.io.FileOutputStream.writeBytes(FileOutputStream.java:???)
>     java.io.FileOutputStream.write(FileOutputStream.java:260)
>     java.io.BufferedOutputStream.write(BufferedOutputStream.java:100)
>     ^-- Holding lock: java.io.BufferedOutputStream@39d70a5[thin lock]
>     org.apache.jackrabbit.core.persistence.util.FileSystemBLOBStore.put(FileSystemBLOBStore.java:88)
>     org.apache.jackrabbit.core.persistence.bundle.util.BundleBinding.writeState(BundleBinding.java:561)
>     org.apache.jackrabbit.core.persistence.bundle.util.BundleBinding.writeBundle(BundleBinding.java:245)
>     org.apache.jackrabbit.core.persistence.bundle.Oracle9PersistenceManager.storeBundle(Oracle9PersistenceManager.java:114)
>     ^-- Holding lock: org.apache.jackrabbit.core.persistence.bundle.Oracle9PersistenceManager@140f7b9[thin lock]
>     org.apache.jackrabbit.core.persistence.bundle.AbstractBundlePersistenceManager.putBundle(AbstractBundlePersistenceManager.java:703)
>     org.apache.jackrabbit.core.persistence.bundle.AbstractBundlePersistenceManager.store(AbstractBundlePersistenceManager.java:526)
>     ^-- Holding lock: org.apache.jackrabbit.core.persistence.bundle.Oracle9PersistenceManager@140f7b9[thin lock]
>     org.apache.jackrabbit.core.persistence.bundle.BundleDbPersistenceManager.store(BundleDbPersistenceManager.java:517)
>     ^-- Holding lock: org.apache.jackrabbit.core.persistence.bundle.Oracle9PersistenceManager@140f7b9[thin lock]
>     org.apache.jackrabbit.core.state.SharedItemStateManager$Update.end(SharedItemStateManager.java:699)
>     org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:873)
>     org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:334)
>     org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:334)
>     org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:307)
>     org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:317)
>     org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:1072)
>     ^-- Holding lock: org.apache.jackrabbit.core.XASessionImpl@1f2653b[thin lock]
>     org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:895)
>     org.apache.jackrabbit.jca.JCASessionHandle.save(JCASessionHandle.java:178)
>     com.qpass.inventory.ingestion.IngestionServiceImpl$1.doInJCR(IngestionServiceImpl.java:140)
>     com.qpass.inventory.model.JCRTemplate.execute(JCRTemplate.java:17)
>     com.qpass.inventory.ingestion.IngestionServiceImpl.ingestProduct(IngestionServiceImpl.java:112)
>     ^-- Holding lock: java.lang.Object@849ca9e[fat lock]
>     com.qpass.inventory.ingestion.bulk.AbstractBulkIngester.ingestProduct(AbstractBulkIngester.java:42)
>     com.qpass.inventory.ingestion.bulk.ZipFileBulkIngester.processFile(ZipFileBulkIngester.java:35)
>     com.qpass.inventory.ingestion.bulk.IngestionWorker.processFile(IngestionWorker.java:26)
>     com.qpass.inventory.ingestion.bulk.IngestionWorker$1.run(IngestionWorker.java:64)
>     org.springframework.scheduling.commonj.DelegatingWork.run(DelegatingWork.java:61)
>     weblogic.work.j2ee.J2EEWorkManager$WorkWithListener.run(J2EEWorkManager.java:245)
>     weblogic.work.ExecuteThread.execute(ExecuteThread.java:206)
>     weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.