You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@felix.apache.org by "metatech (JIRA)" <ji...@apache.org> on 2014/02/21 11:14:19 UTC
[jira] [Comment Edited] (FELIX-3067) Prevent Deadlock Situation in
Felix.acquireGlobalLock
[ https://issues.apache.org/jira/browse/FELIX-3067?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13908140#comment-13908140 ]
metatech edited comment on FELIX-3067 at 2/21/14 10:12 AM:
-----------------------------------------------------------
With ServiceMix 4.5.3 (containing Felix 3.2.2), here are the 2 threads involved in the deadlock when trying to acquire the Felix global lock together with the "logger" lock. Check for the 4 -----> below.
{code}
"FelixPackageAdmin" daemon prio=6 tid=0x0000000008df2800 nid=0x2f6c waiting for monitor entry [0x00000000098ae000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock <0x00000000c02d4010> (a org.apache.log4j.sift.MDCSiftingAppender)
-----> Trying to acquire log lock
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at org.ops4j.pax.logging.service.internal.PaxLoggerImpl.error(PaxLoggerImpl.java:159)
at org.ops4j.pax.logging.internal.TrackingLogger.error(TrackingLogger.java:96)
at org.apache.commons.logging.internal.JclLogger.error(JclLogger.java:164)
at org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution.execute(RunnableTimedExecution.java:109)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener.maybeCloseApplicationContextFor(ContextLoaderListener.java:798)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$ContextBundleListener.handleEvent(ContextLoaderListener.java:242)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$BaseListener.bundleChanged(ContextLoaderListener.java:172)
at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3879)
at org.apache.felix.framework.Felix.stopBundle(Felix.java:2268)
at org.apache.felix.framework.Felix$RefreshHelper.stop(Felix.java:4668)
-----> Global lock acquired
at org.apache.felix.framework.Felix.refreshPackages(Felix.java:3699)
at org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:365)
at java.lang.Thread.run(Thread.java:662)
"Timer-2" daemon prio=6 tid=0x0000000010202000 nid=0x23cc in Object.wait() [0x000000001352e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
-----> Trying to acquire global lock
at org.apache.felix.framework.Felix.acquireGlobalLock(Felix.java:4995)
- locked <0x00000000c082b910> (a [Ljava.lang.Object;)
at org.apache.felix.framework.Felix.access$600(Felix.java:79)
at org.apache.felix.framework.Felix$StatefulResolver.resolve(Felix.java:4177)
at org.apache.felix.framework.ModuleImpl.searchDynamicImports(ModuleImpl.java:1448)
at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:759)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.resolver.WireModuleImpl.getClass(WireModuleImpl.java:97)
at org.apache.felix.framework.ModuleImpl.searchImports(ModuleImpl.java:1426)
at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:747)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.Felix.loadBundleClass(Felix.java:1654)
at org.apache.felix.framework.BundleImpl.loadClass(BundleImpl.java:909)
at org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
at org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.ops4j.pax.logging.util.OsgiUtil.loadClass(OsgiUtil.java:99)
at org.apache.log4j.OsgiThrowableRenderer.findClass(OsgiThrowableRenderer.java:221)
at org.apache.log4j.OsgiThrowableRenderer.formatElement(OsgiThrowableRenderer.java:134)
at org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:105)
at org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:52)
at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:89)
- locked <0x00000000c482ac88> (a org.apache.log4j.spi.ThrowableInformation)
at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x00000000c02d6688> (a org.apache.log4j.DailyRollingFileAppender)
at org.apache.log4j.sift.MDCSiftingAppender.append(MDCSiftingAppender.java:80)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
-----> Log lock acquired
- locked <0x00000000c02d4010> (a org.apache.log4j.sift.MDCSiftingAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at org.ops4j.pax.logging.service.internal.PaxLoggerImpl.warn(PaxLoggerImpl.java:151)
at org.ops4j.pax.logging.internal.TrackingLogger.warn(TrackingLogger.java:91)
at org.apache.commons.logging.internal.JclLogger.warn(JclLogger.java:151)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1010)
at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.doClose(AbstractOsgiBundleApplicationContext.java:197)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.access$501(AbstractDelegatedExecutionApplicationContext.java:69)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$2.run(AbstractDelegatedExecutionApplicationContext.java:214)
at org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.normalClose(AbstractDelegatedExecutionApplicationContext.java:210)
at org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.close(DependencyWaiterApplicationContextExecutor.java:374)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.doClose(AbstractDelegatedExecutionApplicationContext.java:236)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:970)
- locked <0x00000000c2778310> (a java.lang.Object)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$3.run(ContextLoaderListener.java:805)
at org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution$MonitoredRunnable.run(RunnableTimedExecution.java:60)
at org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:70)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
{code}
was (Author: metatech):
With ServiceMix 4.5.3 (containing Felix 3.2.2), here are the 2 threads involved in the deadlock when trying to acquire the Felix global lock together with the "logger" lock. Check for the 4 -----> below.
{code}
"FelixPackageAdmin" daemon prio=6 tid=0x0000000008df2800 nid=0x2f6c waiting for monitor entry [0x00000000098ae000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231)
- waiting to lock <0x00000000c02d4010> (a org.apache.log4j.sift.MDCSiftingAppender)
-----> Trying to acquire lock lock
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at org.ops4j.pax.logging.service.internal.PaxLoggerImpl.error(PaxLoggerImpl.java:159)
at org.ops4j.pax.logging.internal.TrackingLogger.error(TrackingLogger.java:96)
at org.apache.commons.logging.internal.JclLogger.error(JclLogger.java:164)
at org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution.execute(RunnableTimedExecution.java:109)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener.maybeCloseApplicationContextFor(ContextLoaderListener.java:798)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$ContextBundleListener.handleEvent(ContextLoaderListener.java:242)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$BaseListener.bundleChanged(ContextLoaderListener.java:172)
at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:807)
at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:729)
at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:610)
at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:3879)
at org.apache.felix.framework.Felix.stopBundle(Felix.java:2268)
at org.apache.felix.framework.Felix$RefreshHelper.stop(Felix.java:4668)
-----> Global lock acquired
at org.apache.felix.framework.Felix.refreshPackages(Felix.java:3699)
at org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:365)
at java.lang.Thread.run(Thread.java:662)
"Timer-2" daemon prio=6 tid=0x0000000010202000 nid=0x23cc in Object.wait() [0x000000001352e000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
-----> Trying to acquire global lock
at org.apache.felix.framework.Felix.acquireGlobalLock(Felix.java:4995)
- locked <0x00000000c082b910> (a [Ljava.lang.Object;)
at org.apache.felix.framework.Felix.access$600(Felix.java:79)
at org.apache.felix.framework.Felix$StatefulResolver.resolve(Felix.java:4177)
at org.apache.felix.framework.ModuleImpl.searchDynamicImports(ModuleImpl.java:1448)
at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:759)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.resolver.WireModuleImpl.getClass(WireModuleImpl.java:97)
at org.apache.felix.framework.ModuleImpl.searchImports(ModuleImpl.java:1426)
at org.apache.felix.framework.ModuleImpl.findClassOrResourceByDelegation(ModuleImpl.java:747)
at org.apache.felix.framework.ModuleImpl.access$400(ModuleImpl.java:72)
at org.apache.felix.framework.ModuleImpl$ModuleClassLoader.loadClass(ModuleImpl.java:1807)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.apache.felix.framework.ModuleImpl.getClassByDelegation(ModuleImpl.java:670)
at org.apache.felix.framework.Felix.loadBundleClass(Felix.java:1654)
at org.apache.felix.framework.BundleImpl.loadClass(BundleImpl.java:909)
at org.springframework.osgi.util.BundleDelegatingClassLoader.findClass(BundleDelegatingClassLoader.java:99)
at org.springframework.osgi.util.BundleDelegatingClassLoader.loadClass(BundleDelegatingClassLoader.java:156)
at java.lang.ClassLoader.loadClass(ClassLoader.java:247)
at org.ops4j.pax.logging.util.OsgiUtil.loadClass(OsgiUtil.java:99)
at org.apache.log4j.OsgiThrowableRenderer.findClass(OsgiThrowableRenderer.java:221)
at org.apache.log4j.OsgiThrowableRenderer.formatElement(OsgiThrowableRenderer.java:134)
at org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:105)
at org.apache.log4j.OsgiThrowableRenderer.doRender(OsgiThrowableRenderer.java:52)
at org.apache.log4j.spi.ThrowableInformation.getThrowableStrRep(ThrowableInformation.java:89)
- locked <0x00000000c482ac88> (a org.apache.log4j.spi.ThrowableInformation)
at org.apache.log4j.spi.LoggingEvent.getThrowableStrRep(LoggingEvent.java:413)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:313)
at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:369)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x00000000c02d6688> (a org.apache.log4j.DailyRollingFileAppender)
at org.apache.log4j.sift.MDCSiftingAppender.append(MDCSiftingAppender.java:80)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
-----> Log lock acquired
- locked <0x00000000c02d4010> (a org.apache.log4j.sift.MDCSiftingAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.Category.callAppenders(Category.java:193)
at org.apache.log4j.Category.forcedLog(Category.java:365)
at org.apache.log4j.Category.log(Category.java:772)
at org.ops4j.pax.logging.service.internal.PaxLoggerImpl.warn(PaxLoggerImpl.java:151)
at org.ops4j.pax.logging.internal.TrackingLogger.warn(TrackingLogger.java:91)
at org.apache.commons.logging.internal.JclLogger.warn(JclLogger.java:151)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1010)
at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.doClose(AbstractOsgiBundleApplicationContext.java:197)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.access$501(AbstractDelegatedExecutionApplicationContext.java:69)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$2.run(AbstractDelegatedExecutionApplicationContext.java:214)
at org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.normalClose(AbstractDelegatedExecutionApplicationContext.java:210)
at org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.close(DependencyWaiterApplicationContextExecutor.java:374)
at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.doClose(AbstractDelegatedExecutionApplicationContext.java:236)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:970)
- locked <0x00000000c2778310> (a java.lang.Object)
at org.springframework.osgi.extender.internal.activator.ContextLoaderListener$3.run(ContextLoaderListener.java:805)
at org.springframework.osgi.extender.internal.util.concurrent.RunnableTimedExecution$MonitoredRunnable.run(RunnableTimedExecution.java:60)
at org.springframework.scheduling.timer.DelegatingTimerTask.run(DelegatingTimerTask.java:70)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
{code}
> Prevent Deadlock Situation in Felix.acquireGlobalLock
> -----------------------------------------------------
>
> Key: FELIX-3067
> URL: https://issues.apache.org/jira/browse/FELIX-3067
> Project: Felix
> Issue Type: Improvement
> Components: Framework
> Affects Versions: framework-3.0.7, framework-3.0.8, framework-3.0.9, framework-3.2.0, framework-3.2.1, fileinstall-3.1.10
> Reporter: Felix Meschberger
> Attachments: FELIX-3067-sling.patch, FELIX-3067.patch, threaddump-ise-deadlock.txt, threads_locked_by_camel_type_converter
>
>
> Every now and then we encounter deadlock situations which involve the Felix.acquireGlobalLock method. In our use case we have the following aspects which contribute to this:
> (a) The Apache Felix Declarative Services implementation stops components (and thus causes service unregistration) while the bundle lock is being held because this happens in a SynchronousBundleListener while handling the STOPPING bundle event. We have to do this to ensure the bundle is not really stopped yet to properly stop the bundle's components.
> (b) Implementing a special class loader which involves dynamically resolving packages which in turn uses the global lock
> (c) Eclipse Gemini Blueprint implementation which operates asynchronously
> (d) synchronization in application classes
> Often times, I would assume that we can self-heal such complex deadlck situations, if we let acquireGlobalLock time out. Looking at the calles of acquireGlobalLock there seems to already be provision to handle this case since acquireGlobalLock returns true only if the global lock has actually been acquired.
> This issue is kind of a companion to FELIX-3000 where deadlocks involve sending service registration events while holding the bundle lock.
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)