[jboss-jira] [JBoss JIRA] Commented: (JBAS-8261) Finalizer and Timer-Log4jService threads deadlock
Bart Berger (JIRA)
jira-events at lists.jboss.org
Thu Sep 2 16:06:52 EDT 2010
[ https://jira.jboss.org/browse/JBAS-8261?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12548738#action_12548738 ]
Bart Berger commented on JBAS-8261:
-----------------------------------
Thanks, David. I finally realized why this apparently very rare deadlock has been seen twice on the same system. Their system clock is set to a date four months ago. That causes JBoss to re-read the log4j.xml file every minute, even though the file has not been modified. (The last-modified date on the file is only a month ago.) The deadlock is only hit after many hundreds of thousands of file reads. I'll check and see if LogManager has also been changed to save the file's last-modified date instead of the system date for the next comparison. In the meantime correcting the system clock will fix this issue for our case, as the log4j.xml file will not be modified.
> Finalizer and Timer-Log4jService threads deadlock
> -------------------------------------------------
>
> Key: JBAS-8261
> URL: https://jira.jboss.org/browse/JBAS-8261
> Project: JBoss Application Server
> Issue Type: Bug
> Security Level: Public(Everyone can see)
> Components: Logging
> Affects Versions: JBossAS-5.1.0.GA
> Environment: OS: Linux (2.6.16.46-0.12-bigsmp)
> JVM: Java HotSpot(TM) Server VM (16.3-b01, mixed mode) (JRE 1.6.0_20)
> Reporter: Bart Berger
> Assignee: David Lloyd
>
> Encountered the following deadlock:
> "Finalizer" daemon prio=8 tid=3 BLOCKED
> at org.jboss.logmanager.LoggerNode.getParentLogger(LoggerNode.java:142)
> Local Variable: org.jboss.logmanager.LoggerNode#362
> at org.jboss.logmanager.LoggerInstance.getParent(LoggerInstance.java:167)
> at org.jboss.logmanager.LoggerInstance.setLevel(LoggerInstance.java:96)
> Local Variable: java.util.logging.Level#2
> Local Variable: org.jboss.logmanager.LogContext#1
> at org.jboss.logmanager.LoggerInstance.finalize(LoggerInstance.java:204)
> at java.lang.ref.Finalizer.$$YJP$$invokeFinalizeMethod(Native Method)
> at java.lang.ref.Finalizer.invokeFinalizeMethod(Finalizer.java)
> at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
> Local Variable: org.jboss.logmanager.LoggerInstance#161
> at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
> at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)
> Local Variable: java.lang.ref.Finalizer#65597
> "Timer-Log4jService" daemon prio=5 tid=25 WAITING
> at sun.misc.Unsafe.$$YJP$$park(Native Method)
> at sun.misc.Unsafe.park(Unsafe.java)
> Local Variable: sun.misc.Unsafe#1
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:747)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:778)
> Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#629
> Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#630
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1114)
> at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:186)
> Local Variable: java.util.concurrent.locks.ReentrantLock$NonfairSync#89
> at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:262)
> Local Variable: java.util.concurrent.locks.ReentrantLock#42
> at org.jboss.logmanager.LoggerInstance.setLevel(LoggerInstance.java:89)
> at org.jboss.logmanager.LoggerInstance.<init>(LoggerInstance.java:53)
> Local Variable: org.jboss.logmanager.LoggerInstance#1049
> Local Variable: java.lang.String#936666
> at org.jboss.logmanager.LoggerNode.getOrCreateLogger(LoggerNode.java:127)
> at org.jboss.logmanager.LogContext.getLogger(LogContext.java:71)
> at org.jboss.logmanager.LogManager.getLogger(LogManager.java:273)
> at java.util.logging.LogManager.demandLogger(LogManager.java:390)
> at java.util.logging.Logger.getLogger(Logger.java:274)
> Local Variable: org.jboss.logmanager.LogManager#1
> at org.jboss.logbridge.LogBridgeHandler.updateLoggers(LogBridgeHandler.java:123)
> Local Variable: java.util.Collections$SynchronizedMap#43
> Local Variable: java.util.Vector$1#3
> Local Variable: org.apache.log4j.spi.RootLogger#1
> Local Variable: org.apache.log4j.Hierarchy#1
> Local Variable: org.apache.log4j.Logger#375
> Local Variable: java.lang.String#582052
> Local Variable: org.jboss.logbridge.LevelMapper#1
> Local Variable: org.jboss.logbridge.LogBridgeHandler#1
> at org.jboss.logbridge.LogNotificationListener.handleNotification(LogNotificationListener.java:67)
> at sun.reflect.GeneratedMethodAccessor203.invoke(<unknown string>)
> Local Variable: sun.reflect.GeneratedMethodAccessor203#1
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> Local Variable: sun.reflect.DelegatingMethodAccessorImpl#458
> at java.lang.reflect.Method.invoke(Method.java:597)
> Local Variable: org.jboss.logbridge.LogNotificationListener#1
> at org.jboss.mx.notification.NotificationListenerProxy.invoke(NotificationListenerProxy.java:153)
> Local Variable: java.lang.String#2851584
> Local Variable: java.lang.Object[]#760535
> Local Variable: org.jboss.mx.notification.NotificationListenerProxy#2
> Local Variable: java.lang.reflect.Method#16042
> at $Proxy73.handleNotification(<unknown string>)
> at org.jboss.mx.util.JBossNotificationBroadcasterSupport.handleNotification(JBossNotificationBroadcasterSupport.java:127)
> Local Variable: $Proxy73#1
> at org.jboss.mx.util.JBossNotificationBroadcasterSupport.sendNotification(JBossNotificationBroadcasterSupport.java:108)
> Local Variable: org.jboss.mx.notification.DefaultListenerRegistration#3
> Local Variable: org.jboss.mx.notification.ListenerRegistry$ListenerRegistrationIterator#1
> at org.jboss.logging.Log4jService.emitReconfigureNotification(Log4jService.java:560)
> Local Variable: org.jboss.logging.Log4jService#1
> Local Variable: javax.management.Notification#1
> at org.jboss.logging.Log4jService$URLWatchTimerTask.reconfigure(Log4jService.java:716)
> at org.jboss.logging.Log4jService$URLWatchTimerTask.run(Log4jService.java:636)
> Local Variable: org.jboss.net.protocol.resource.ResourceURLConnection#1
> at java.util.TimerThread.mainLoop(Timer.java:512)
> Local Variable: java.lang.Object#18446
> Local Variable: org.jboss.logging.Log4jService$URLWatchTimerTask#1
> Local Variable: java.util.TaskQueue#5
> at java.util.TimerThread.run(Timer.java:462)
> The timer thread ran logging configuration while the finalizer was processing LoggerInstance objects.
> The Finalizer thread calls context.levelTreeLock.lock() in LoggerInstance.setLevel(), then enters a synchronized code block in LoggerNode.getParentLogger(). The configuration thread enters a synchronized code block in LoggerNode.getOrCreateLogger(), then creates a new LoggerInstance which calls context.levelTreeLock.lock() in LoggerInstance.setLevel().
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: https://jira.jboss.org/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the jboss-jira
mailing list