Uploaded image for project: 'Application Server 3  4  5 and 6'
  1. Application Server 3 4 5 and 6
  2. JBAS-8261

Finalizer and Timer-Log4jService threads deadlock

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Obsolete
    • Icon: Major Major
    • No Release
    • JBossAS-5.1.0.GA
    • Logging
    • None
    • 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)

    • Hide

      Don't know. Seen only once so far. User may have edited jboss-log4j.xml to cause the deadlock, but that is not confirmed. The issue was not discovered until much later when the Finalizer queue grew large enough to consume all available memory.

      Show
      Don't know. Seen only once so far. User may have edited jboss-log4j.xml to cause the deadlock, but that is not confirmed. The issue was not discovered until much later when the Finalizer queue grew large enough to consume all available memory.

      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().

              dlloyd@redhat.com David Lloyd
              bberger_jira Bart Berger (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Created:
                Updated:
                Resolved: