6 Replies Latest reply on Apr 26, 2013 12:32 PM by nsabina

    Performance bottleneck in LogManager

    nsabina
    nsabina Apr 24, 2013 12:37 PM

      We only see this happening under the load however I would like to rule out some logging misconfiguration on our side.

      Thread dump taken when OOM occurs shows that a thread Worker1168_QueryProcessorQueue1201675 owns a lock for CopyOnWriteWeakMap@0x0000004829F3AAA0

      There are other 10 worker threads waiting to perform some DQP logging blocked by this lock.

      Owner of the lock Worker1168_QueryProcessorQueue1201675 is in "waiting on condition" status.

       

      2LKMONINUSE  sys_mon_t:0x00000048C0D78228 infl_mon_t: 0x00000048C0D782A0:
      3LKMONOBJECT   org/jboss/logmanager/CopyOnWriteWeakMap@0x0000004829F3AAA0: Flat locked by "Worker1168_QueryProcessorQueue1201675" (0x00000049E4E31000), entry count 1
      3LKWAITERQ        Waiting to enter:
      3LKWAITER            "Worker1048_QueryProcessorQueue1201677" (0x0000004A1CC5BD00)
      3LKWAITER            "Worker1087_QueryProcessorQueue1201678" (0x0000004A1AB72100)
      3LKWAITER            "Worker1082_QueryProcessorQueue1201425" (0x0000004A75BD8A00)
      3LKWAITER            "Worker1108_QueryProcessorQueue1201596" (0x0000004A1EB9CC00)
      3LKWAITER            "Worker1132_QueryProcessorQueue1201682" (0x0000004A1EBBDB00)
      3LKWAITER            "Worker1129_QueryProcessorQueue1201627" (0x0000004A75B9E700)
      3LKWAITER            "Worker1162_QueryProcessorQueue1201583" (0x0000004A763A6900)
      3LKWAITER            "Worker1164_QueryProcessorQueue1201673" (0x0000004A1EBA6D00)
      3LKWAITER            "Worker1185_QueryProcessorQueue1201609" (0x0000004A7644B800)
      3LKWAITER            "Worker1195_QueryProcessorQueue1201680" (0x0000004A764BF600)

       

      Can this bottleneck be resolved by tweaking some JBoss logging configuration? Other things we should look into in application code to relief such bottleneck ?

       

      Below are stacktrace of the thread that owns the lock and one of the waiting threads. Complete thread dump is attached

       

      Thread Name Worker1168_QueryProcessorQueue1201675
      State Waiting on condition
      Monitor Owns Monitor Lock on org/jboss/logmanager/CopyOnWriteWeakMap@0x0000004829F3AAA0
      Java Stack at java/lang/Object.clone(Native Method)
      at org/jboss/logmanager/FastCopyHashMap.(FastCopyHashMap.java:128(Compiled Code))
      at org/jboss/logmanager/CopyOnWriteWeakMap.cleanCopyForMod(CopyOnWriteWeakMap.java:76(Compiled Code))
      at org/jboss/logmanager/CopyOnWriteWeakMap.putIfAbsent(CopyOnWriteWeakMap.java:104(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:156(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:164(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:164(Compiled Code))
      at org/jboss/logmanager/LogContext.getLogger(LogContext.java:122(Compiled Code))
      at org/jboss/logmanager/LogManager.getLogger(LogManager.java:342(Compiled Code))
      at org/jboss/logmanager/LogManager.getLogger(LogManager.java:44(Compiled Code))
      at java/util/logging/LogManager.demandLogger(LogManager.java:365(Compiled Code))
      at java/util/logging/Logger.getLogger(Logger.java:339(Compiled Code))
      at org/jboss/logmanager/Logger.getLogger(Logger.java:58(Compiled Code))
      at org/jboss/logging/JBossLogManagerProvider.doGetLogger(JBossLogManagerProvider.java:56(Compiled Code))
      at org/jboss/logging/JBossLogManagerProvider.getLogger(JBossLogManagerProvider.java:47(Compiled Code))
      at org/jboss/logging/Logger.getLogger(Logger.java:2163(Compiled Code))
      at org/teiid/jboss/JBossLogger.getLogger(JBossLogger.java:105(Compiled Code))
      at org/teiid/jboss/JBossLogger.isEnabled(JBossLogger.java:37(Compiled Code))
      at org/teiid/logging/LogManager.isMessageToBeRecorded(LogManager.java:380(Compiled Code))
      at org/teiid/dqp/internal/datamgr/ConnectorManager.logSRCCommand(ConnectorManager.java:167(Compiled Code))
      at org/teiid/dqp/internal/datamgr/ConnectorWorkItem.close(ConnectorWorkItem.java:154(Compiled Code))
      at org/teiid/dqp/internal/process/DataTierTupleSource$2.call(DataTierTupleSource.java:455(Compiled Code))
      at org/teiid/dqp/internal/process/DataTierTupleSource$2.call(DataTierTupleSource.java:452(Compiled Code))
      at java/util/concurrent/FutureTask$Sync.innerRun(FutureTask.java:345(Compiled Code))
      at java/util/concurrent/FutureTask.run(FutureTask.java:177(Compiled Code))
      at org/teiid/dqp/internal/process/DQPCore$FutureWork.run(DQPCore.java:118(Compiled Code))
      at org/teiid/dqp/internal/process/DQPWorkContext.runInContext(DQPWorkContext.java:249(Compiled Code))
      at org/teiid/dqp/internal/process/ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:123(Compiled Code))
      at org/teiid/dqp/internal/process/ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:298(Compiled Code))
      at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1121)
      at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614(Compiled Code))
      at java/lang/Thread.run(Thread.java:779(Compiled Code))
             
      Native Stack No Native stack trace available

       

      Thread Name Worker1129_QueryProcessorQueue1201627
      State Blocked
      Monitor Waiting for Monitor Lock on org/jboss/logmanager/CopyOnWriteWeakMap@0x0000004829F3AAA0
      Java Stack at org/jboss/logmanager/CopyOnWriteWeakMap.putIfAbsent(CopyOnWriteWeakMap.java:98(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:156(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:164(Compiled Code))
      at org/jboss/logmanager/LoggerNode.getOrCreate(LoggerNode.java:164(Compiled Code))
      at org/jboss/logmanager/LogContext.getLogger(LogContext.java:122(Compiled Code))
      at org/jboss/logmanager/LogManager.getLogger(LogManager.java:342(Compiled Code))
      at org/jboss/logmanager/LogManager.getLogger(LogManager.java:44(Compiled Code))
      at java/util/logging/LogManager.demandLogger(LogManager.java:365(Compiled Code))
      at java/util/logging/Logger.getLogger(Logger.java:339(Compiled Code))
      at org/jboss/logmanager/Logger.getLogger(Logger.java:58(Compiled Code))
      at org/jboss/logging/JBossLogManagerProvider.doGetLogger(JBossLogManagerProvider.java:56(Compiled Code))
      at org/jboss/logging/JBossLogManagerProvider.getLogger(JBossLogManagerProvider.java:47(Compiled Code))
      at org/jboss/logging/Logger.getLogger(Logger.java:2163(Compiled Code))
      at org/teiid/jboss/JBossLogger.getLogger(JBossLogger.java:105(Compiled Code))
      at org/teiid/jboss/JBossLogger.isEnabled(JBossLogger.java:37(Compiled Code))
      at org/teiid/logging/LogManager.isMessageToBeRecorded(LogManager.java:380(Compiled Code))
      at org/teiid/dqp/internal/datamgr/ConnectorManager.logSRCCommand(ConnectorManager.java:167(Compiled Code))
      at org/teiid/dqp/internal/datamgr/ConnectorWorkItem.handleError(ConnectorWorkItem.java:186(Compiled Code))
      at org/teiid/dqp/internal/datamgr/ConnectorWorkItem.execute(ConnectorWorkItem.java:260(Compiled Code))
      at org/teiid/dqp/internal/process/DataTierTupleSource.getResults(DataTierTupleSource.java:425(Compiled Code))
      at org/teiid/dqp/internal/process/DataTierTupleSource$1.call(DataTierTupleSource.java:170(Compiled Code))
      at org/teiid/dqp/internal/process/DataTierTupleSource$1.call(DataTierTupleSource.java:167(Compiled Code))
      at java/util/concurrent/FutureTask$Sync.innerRun(FutureTask.java:345(Compiled Code))
      at java/util/concurrent/FutureTask.run(FutureTask.java:177(Compiled Code))
      at org/teiid/dqp/internal/process/DQPCore$FutureWork.run(DQPCore.java:118(Compiled Code))
      at org/teiid/dqp/internal/process/DQPWorkContext.runInContext(DQPWorkContext.java:249(Compiled Code))
      at org/teiid/dqp/internal/process/ThreadReuseExecutor$RunnableWrapper.run(ThreadReuseExecutor.java:123(Compiled Code))
      at org/teiid/dqp/internal/process/ThreadReuseExecutor$3.run(ThreadReuseExecutor.java:298(Compiled Code))
      at java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1121)
      at java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614(Compiled Code))
      at java/lang/Thread.run(Thread.java:779(Compiled Code))
             
      Native Stack No Native stack trace available
      • 1353 Views
      • Tags:
        • 1. Re: Performance bottleneck in LogManager
          rareddy
          rareddy Apr 24, 2013 1:43 PM (in response to nsabina)

          Sabina,

           

          Looks like you are configured at the DEBUG level for logging, if you want you can take that to INFO/WARNING, that will at least avoid using the too many log messages. Not about what is causing this perticular issue. So, how much percentage of overhead you are seeing because of this?

           

          Ramesh..

            • Actions
          • 2. Re: Performance bottleneck in LogManager
            shawkins
            shawkins Apr 24, 2013 1:59 PM (in response to rareddy)

            > Looks like you are configured at the DEBUG level for logging

             

            I'm not sure that matters.  The logger creation and locking is coming from isMessageToBeRecorded, which will be called regardless of whatever the underlying level is.

             

            We however hadn't observed this particular problem yet.  And it appears that the internals of JBoss logging should be caching the loggers, but if that's not actually happening then our JBossLogger should use a cache of loggers similar to the JavaLogger (which did exhibit some of the same behavior of logger instances not being cached) - https://github.com/teiid/teiid/blob/master/api/src/main/java/org/teiid/logging/JavaLogger.java

             

            If that generally improves timings / helps resolve your issue, then just log a JIRA and we'll add it to the JBossLogger.

             

            Steve 

              • Actions
            • 3. Re: Performance bottleneck in LogManager
              nsabina
              nsabina Apr 24, 2013 2:15 PM (in response to rareddy)

              Yes Ramesh, we do keep debug only for our development purposes and not enable it on a customer site. We were also going through series of performance improvements in the different areas of the application.  This dump however was taken after most of the fixes were put in plus auto refresh was disabled ( most of high CPU related concerns were tied to auto refresh ).

              I will have to research more to give you the overhead percentage but overall symptoms are that system becomes slow and unresponsive as more users are logging in. As far as I can see in profiler this is due to number of blocked threads growing. At some point system crashed with OOM. Heap dump did not show anything but BufferManagerImpl. As far blocked threads at the time of OOM there were 40 of them. Some related to H2 transactions and we already know what is it and working on those. The example above is roughly a quarter of blocked threads and I am just trying to see if this is not and issue and/or there is a way to adjust it with settings or configuration .

               

              Thanks,

              Sabina

                • Actions
              • 4. Re: Performance bottleneck in LogManager
                nsabina
                nsabina Apr 24, 2013 3:05 PM (in response to shawkins)

                Steve ,

                 

                You are correct , isMessageToBeRecorded appears in the stack trace of all the blocked threads

                  • Actions
                • 5. Re: Performance bottleneck in LogManager
                  shawkins
                  shawkins Apr 26, 2013 10:49 AM (in response to nsabina)

                  I do see in the container that some of the caching of logging nodes are based upon thread locals.  So it is possible at least for initial creation for threads to be locked in the same place.  However you'd expect this to have a relatively minor amount of overhead and subsequent access should use a cached logger (although I haven't extensively tested the latter).  I'll just go ahead and commit the usage of locally cached loggers into the JBossLogger under https://issues.jboss.org/browse/TEIID-2488 since it is a very benign change.  More than likely this will just push your issue a little further and/or make the actual problem clearer.

                   

                  Steve

                    • Actions
                  • 6. Re: Performance bottleneck in LogManager
                    nsabina
                    nsabina Apr 26, 2013 12:32 PM (in response to shawkins)

                    Thank you Steve.

                     

                    I will incorporate it into load tests on my local and will raise further questions if any.

                     

                    Sabina

                      • Actions