Description
John Lee opened SPR-7718 and commented
Deploying EAR on Weblogic 10.0. Root XmlWebApplicationContext ends up w/ about 300 bean definitions from 3 WARs, which takes long enough to instantiate to see this behavior. Each WAR publishes web services specified in Spring contexts as Apache CXF endpoints. Service implementations are annotated so that an aspect can monitor traffic to all services. The traffic is reported to a monitoring process (deployed separately, but also a CXF webservice) at set intervals by Quartz jobs. The Quartz jobs are not wired via Spring integration; the Spring context just declares an org.quartz.Scheduler which gets injected into "updater" classes that add associated jobs right after instantiation (@PostConstruct
).
This architecture has worked well for over a year, but we recently added a JAX-WS Handler to the traffic reporting, and this seemed to affect the timing of the context initialization enough that this deadlock started appearing (and it happens everytime without fail, usually for the same bean names as viewed in debugger, although the same EAR deployed on JBoss 4.2 works fine; different classloader architecture).
What it looks like is that one of the Quartz jobs triggers while Spring is in the process of pre-instantiating singletons, and an aspect on the traffic reporting client (picked up via <component-scan/> and annotated w/ AspectJ @Aspect
and Spring @Component
, pointcuts defined AspectJ-style) required for the Quartz job is lazily instantiated for some reason (a guess, from the LazySingletonAspectInstanceFactoryDecorator.getAspectInstance call in the stack trace), leading to the deadlock. Tweaking the triggers so that the start date is some time after instantiation, e.g. 30 sec., is my current workaround, but I thought that if this is a bug in Spring (didn't see any other reports of this scenario in the forums or in general web search), it's worth fixing.
The last thing written to the log is:
[many other services being bound to endpoints...]
16:09:24,496 INFO ReflectionServiceFactoryBean:437 - Creating Service {http://services.mycompany.com/diagnostics}Diagnostics from class com.mycompany.services.Diagnostics
16:09:26,275 INFO QuartzScheduler:461 - Scheduler QuartzScheduler_$_NON_CLUSTERED started.
16:09:26,275 INFO PeriodicalUpdater:73 - ConfigurationManagerUpdater scheduled with interval 5000 ms.
16:09:29,268 INFO ServerImpl:91 - Setting the server's publish address to be /Diagnostics
Here's the thread dump:
Found one Java-level deadlock:
"QuartzScheduler_Worker-2":
waiting to lock monitor 0x001b702c (object 0x0a7e7e80, a java.util.concurrent.
ConcurrentHashMap),
which is held by "[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Defa
ult (self-tuning)'"
"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'"
:
waiting to lock monitor 0x001b6d4c (object 0x0a7e7be0, a java.util.concurrent.
ConcurrentHashMap),
which is held by "QuartzScheduler_Worker-2"
Java stack information for the threads listed above:
"QuartzScheduler_Worker-2":
at org.springframework.beans.factory.support.DefaultListableBeanFactory.
getBeanDefinitionNames(DefaultListableBeanFactory.java:192)
-
waiting to lock <0x0a7e7e80> (a java.util.concurrent.ConcurrentHashMap
)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.
getBeanNamesForType(DefaultListableBeanFactory.java:209)
at org.springframework.beans.factory.BeanFactoryUtils.beanNamesForTypeIn
cludingAncestors(BeanFactoryUtils.java:187)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.
findAutowireCandidates(DefaultListableBeanFactory.java:652)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.
resolveDependency(DefaultListableBeanFactory.java:610)
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanP
ostProcessor$AutowiredFieldElement.inject(AutowiredAnnotationBeanPostProcessor.j
ava:412)
at org.springframework.beans.factory.annotation.InjectionMetadata.inject
Fields(InjectionMetadata.java:105)
at org.springframework.beans.factory.annotation.AutowiredAnnotationBeanP
ostProcessor.postProcessAfterInstantiation(AutowiredAnnotationBeanPostProcessor.
java:240)
at org.springframework.beans.factory.support.AbstractAutowireCapableBean
Factory.populateBean(AbstractAutowireCapableBeanFactory.java:959)
at org.springframework.beans.factory.support.AbstractAutowireCapableBean
Factory.doCreateBean(AbstractAutowireCapableBeanFactory.java:472)
at org.springframework.beans.factory.support.AbstractAutowireCapableBean
Factory$1.run(AbstractAutowireCapableBeanFactory.java:409)
at java.security.AccessController.doPrivileged(Native Method)
at org.springframework.beans.factory.support.AbstractAutowireCapableBean
Factory.createBean(AbstractAutowireCapableBeanFactory.java:380)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getOb
ject(AbstractBeanFactory.java:264)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistr
y.getSingleton(DefaultSingletonBeanRegistry.java:222) -
locked <0x0a7e7be0> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBe
an(AbstractBeanFactory.java:261)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean
(AbstractBeanFactory.java:185)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean
(AbstractBeanFactory.java:164)
at org.springframework.aop.aspectj.annotation.BeanFactoryAspectInstanceF
actory.getAspectInstance(BeanFactoryAspectInstanceFactory.java:76)
at org.springframework.aop.aspectj.annotation.LazySingletonAspectInstanc
eFactoryDecorator.getAspectInstance(LazySingletonAspectInstanceFactoryDecorator.
java:47) -
locked <0x0ab1eb00> (a org.springframework.aop.aspectj.annotation.Lazy
SingletonAspectInstanceFactoryDecorator)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMet
hodWithGivenArgs(AbstractAspectJAdvice.java:627)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMet
hod(AbstractAspectJAdvice.java:609)
at org.springframework.aop.aspectj.AspectJMethodBeforeAdvice.before(Aspe
ctJMethodBeforeAdvice.java:39)
at org.springframework.aop.framework.adapter.MethodBeforeAdviceIntercept
or.invoke(MethodBeforeAdviceInterceptor.java:49)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
ReflectiveMethodInvocation.java:160)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.p
roceed(MethodInvocationProceedingJoinPoint.java:77)
at com.mycompany.services.commons.aspects.ClientProxyAspect.fillRequ
estInfo(ClientProxyAspect.java:68)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMet
hodWithGivenArgs(AbstractAspectJAdvice.java:627)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMet
hod(AbstractAspectJAdvice.java:616)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAro
undAdvice.java:64)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
ReflectiveMethodInvocation.java:160)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invok
e(ExposeInvocationInterceptor.java:89)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(
ReflectiveMethodInvocation.java:171)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterc
eptor.intercept(Cglib2AopProxy.java:635)
at com.mycompany.services.bindings.trafficreporter.client.ws.ConfigurationW
SClient$$EnhancerByCGLIB$$b4564aa2.getConfiguration(<generated>)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
sorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at com.mycompany.services.trafficreporter.client.Clie
ntProxy.executeMethod(ClientProxy.java:159)
at com.mycompany.services.trafficreporter.client.Clie
ntProxy.getConfiguration(ClientProxy.java:95)
at com.mycompany.services.trafficreporter.manager.updater.Configurat
ionManagerJob.updateAction(ConfigurationManagerJob.java:63)
at com.mycompany.services.trafficreporter.manager.updater.UpdateJob.
execute(UpdateJob.java:83)
at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.j
ava:534)
"[ACTIVE] ExecuteThread: '0' for queue: 'weblogic.kernel.Default (self-tuning)'"
:
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistr
y.getSingleton(DefaultSingletonBeanRegistry.java:180) -
waiting to lock <0x0a7e7be0> (a java.util.concurrent.ConcurrentHashMap
)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistr
y.getSingleton(DefaultSingletonBeanRegistry.java:166)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBe
an(AbstractBeanFactory.java:206)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean
(AbstractBeanFactory.java:185)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean
(AbstractBeanFactory.java:164)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.
preInstantiateSingletons(DefaultListableBeanFactory.java:429) -
locked <0x0a7e7e80> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.context.support.AbstractApplicationContext.finish
BeanFactoryInitialization(AbstractApplicationContext.java:728)
at org.springframework.context.support.AbstractApplicationContext.refres
h(AbstractApplicationContext.java:380) -
locked <0x0a7e7610> (a java.lang.Object)
at org.springframework.web.context.ContextLoader.createWebApplicationCon
text(ContextLoader.java:255)
at org.springframework.web.context.ContextLoader.initWebApplicationConte
xt(ContextLoader.java:199)
at org.springframework.web.context.ContextLoaderListener.contextInitiali
zed(ContextLoaderListener.java:45)
at weblogic.servlet.internal.EventsManager$FireContextListenerAction.run
(EventsManager.java:458)
at weblogic.security.acl.internal.AuthenticatedSubject.doAs(Authenticate
dSubject.java:321)
at weblogic.security.service.SecurityManager.runAs(Unknown Source)
at weblogic.servlet.internal.EventsManager.notifyContextCreatedEvent(Eve
ntsManager.java:168)
at weblogic.servlet.internal.WebAppServletContext.preloadResources(WebAp
pServletContext.java:1721) -
locked <0x0a5f7d50> (a weblogic.servlet.internal.WebAppServletContext)
at weblogic.servlet.internal.WebAppServletContext.start(WebAppServletCon
text.java:2890)
at weblogic.servlet.internal.WebAppModule.startContexts(WebAppModule.jav
a:948)
at weblogic.servlet.internal.WebAppModule.start(WebAppModule.java:353)
at weblogic.application.internal.flow.ModuleStateDriver$3.next(ModuleSta
teDriver.java:204)
at weblogic.application.utils.StateMachineDriver.nextState(StateMachineD
river.java:26)
at weblogic.application.internal.flow.ModuleStateDriver.start(ModuleStat
eDriver.java:60)
at weblogic.application.internal.flow.ScopedModuleDriver.start(ScopedMod
uleDriver.java:200)
at weblogic.application.internal.flow.ModuleListenerInvoker.start(Module
ListenerInvoker.java:117)
at weblogic.application.internal.flow.ModuleStateDriver$3.next(ModuleSta
teDriver.java:204)
at weblogic.application.utils.StateMachineDriver.nextState(StateMachineD
river.java:26)
at weblogic.application.internal.flow.ModuleStateDriver.start(ModuleStat
eDriver.java:60)
at weblogic.application.internal.flow.StartModulesFlow.activate(StartMod
ulesFlow.java:26)
at weblogic.application.internal.BaseDeployment$2.next(BaseDeployment.ja
va:635)
at weblogic.application.utils.StateMachineDriver.nextState(StateMachineD
river.java:26)
at weblogic.application.internal.BaseDeployment.activate(BaseDeployment.
java:212)
at weblogic.application.internal.DeploymentStateChecker.activate(Deploym
entStateChecker.java:154)
at weblogic.deploy.internal.targetserver.AppContainerInvoker.activate(Ap
pContainerInvoker.java:80)
at weblogic.deploy.internal.targetserver.BasicDeployment.activate(BasicD
eployment.java:182)
at weblogic.deploy.internal.targetserver.BasicDeployment.activateFromSer
verLifecycle(BasicDeployment.java:359)
at weblogic.management.deploy.internal.DeploymentAdapter$1.doActivate(De
ploymentAdapter.java:51)
at weblogic.management.deploy.internal.DeploymentAdapter.activate(Deploy
mentAdapter.java:196)
at weblogic.management.deploy.internal.AppTransition$2.transitionApp(App
Transition.java:30)
at weblogic.management.deploy.internal.ConfiguredDeployments.transitionA
pps(ConfiguredDeployments.java:233)
at weblogic.management.deploy.internal.ConfiguredDeployments.activate(Co
nfiguredDeployments.java:169)
at weblogic.management.deploy.internal.ConfiguredDeployments.deploy(Conf
iguredDeployments.java:123)
at weblogic.management.deploy.internal.DeploymentServerService.resume(De
ploymentServerService.java:173)
at weblogic.management.deploy.internal.DeploymentServerService.start(Dep
loymentServerService.java:89)
at weblogic.t3.srvr.SubsystemRequest.run(SubsystemRequest.java:64)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:200)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:172)
Found 1 deadlock.
Affects: 2.5.6
Issue Links:
- Performance bottleneck and potential thread deadlock in DefaultSingletonBeanRegistry [SPR-8471] #13117 Performance bottleneck and potential thread deadlock in DefaultSingletonBeanRegistry
- Support initial delay attribute for @Scheduled and <task:scheduled> [SPR-7022] #11684 Support initial delay attribute for
@Scheduled
and task:scheduled
11 votes, 14 watchers