3123341 - LoggingAPI causes bottleneck during high load of messages in SAP Process Integration

In SAP Process Integration/SAP Process Orchestration system, you started to notice severe performance issues in your system related to the message processing.

Messages are increasing in the Scheduled/To Be Delivered status and the backlog in the DispatchDisp queue is also increasing.

If you capture some thread dumps while the issue is happening, you can see that several threads are blocked waiting to lock a resource. Similar to the stack below:

• java.lang.Thread.State: BLOCKED (on object monitor)
   at com.sap.engine.messaging.impl.core.queue.Queue.checkAndIncreaseWorkers()V(Queue.java:665)
   - waiting to lock <0x00000006a51d8ff0> (a com.sap.engine.messaging.impl.core.queue.provider.WeightedRoundRobinQueueProvider)

If you search for the resource above (0x00000006a51d8ff0), you can see that it is currently locked by a thread which is using the LoggingAPI to write logs into the OS (default traces):

• "MS Queue Worker [Dispatch]" #3046 prio=5 os_prio=0 cpu=7984480.00 [reset 7984270.00] ms elapsed=12846.70 [reset 12609.73] s allocated=3662732934712 B (3.33 TB) [reset 3662705029776 B (3.33 TB)] defined_classes=31
  io= file i/o: 2237827/265280220635 B, net i/o: 475543309/1885648 B, files opened:3, socks opened:2  [reset file i/o: 2236547/265280220120 B, net i/o: 475538959/1866003 B, files opened:2, socks opened:2 ] 
  user="" isapplicationthread="true" tid=0x00007f0110200800 nid=0xe8e7 / 59623  pthread-id=139639260653312 runnable   [_thread_blocked (_at_safepoint), stack(0x00007f004c672000,0x00007f004c873000)] [0x00007f004c86f000]
     java.lang.Thread.State: RUNNABLE
   at java.io.FileOutputStream.writeBytesWithPath([BIIZLjava/lang/String;)V(Native Method)
   at java.io.FileOutputStream.write([BII)V(FileOutputStream.java:341)
   at sun.nio.cs.StreamEncoder.writeBytes()V(StreamEncoder.java:221)
   at sun.nio.cs.StreamEncoder.implFlushBuffer()V(StreamEncoder.java:291)
   at sun.nio.cs.StreamEncoder.implFlush()V(StreamEncoder.java:295)
   at sun.nio.cs.StreamEncoder.flush()V(StreamEncoder.java:141)
   - locked <0x000000065b44bdd0> (a java.io.OutputStreamWriter)
   at java.io.OutputStreamWriter.flush()V(OutputStreamWriter.java:229)
   at com.sap.tc.logging.StreamLog.flushInt()V(StreamLog.java:192)
   - locked <0x000000069ab844b0> (a com.sap.tc.logging.FileLog)
   at com.sap.tc.logging.Log.flush()V(Log.java:572)
   at com.sap.tc.logging.Log.writeInternalByAPI(Lcom/sap/tc/logging/LogRecord;)Lcom/sap/tc/logging/LogRecord;(Log.java:905)
   at com.sap.tc.logging.LogController.writeToLogs(Ljava/util/Collection;Lcom/sap/tc/logging/LogRecord;)Lcom/sap/tc/logging/LogRecord;(LogController.java:2890)
   at com.sap.tc.logging.LogController.messageInternal(Lcom/sap/tc/logging/LogRecord;)Lcom/sap/tc/logging/LogRecord;(LogController.java:2010)
   at com.sap.tc.logging.LogController.prepareLogRecord(Lcom/sap/tc/logging/LogRecord;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Lcom/sap/tc/logging/LogRecord;(LogController.java:2112)
   at com.sap.tc.logging.LogController.logTInt(ILcom/sap/tc/logging/LogController;[Lcom/sap/tc/logging/LogController;Ljava/lang/String;Ljava/lang/String;I[Ljava/lang/Object;Ljava/lang/Throwable;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Lcom/sap/tc/logging/LogRecord;(LogController.java:2172)
   at com.sap.tc.logging.LogController.logTInt(ILcom/sap/tc/logging/LogController;[Lcom/sap/tc/logging/LogController;Ljava/lang/String;Ljava/lang/String;I[Ljava/lang/Object;Ljava/lang/Throwable;Ljava/lang/String;Ljava/lang/String;Ljava/lang/String;)Lcom/sap/tc/logging/LogRecord;(LogController.java:2149)
   at com.sap.tc.logging.Location.entering(Ljava/lang/String;[Ljava/lang/Object;)Lcom/sap/tc/logging/LogRecord;(Location.java:8598)
   at com.sap.engine.messaging.impl.util.Trace.entering(Ljava/lang/String;[Ljava/lang/Object;)V(Trace.java:141)
   at com.sap.engine.messaging.impl.core.queue.provider.limitation.ReceiverPerInterfaceLimitation.unlimitedProcessing(Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;)Z(ReceiverPerInterfaceLimitation.java:147)
   at com.sap.engine.messaging.impl.core.queue.provider.limitation.ReceiverPerInterfaceLimitation.hasResources(Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;)Z(ReceiverPerInterfaceLimitation.java:272)
   at com.sap.engine.messaging.impl.core.queue.provider.limitation.CompositeLimitation.hasResources(Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;)Z(CompositeLimitation.java:137)
   at com.sap.engine.messaging.impl.core.queue.provider.LimitedQueueProvider.capacityAvailable(Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;)Z(LimitedQueueProvider.java:196)
   at com.sap.engine.messaging.impl.core.queue.Queue.isSaturated(Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;)Z(Queue.java:1815)
   - locked <0x00000006cb1b7ce8> (a java.lang.Object)
   at com.sap.engine.messaging.impl.core.queue.provider.WeightedRoundRobinQueueProvider.removeNext()Lcom/sap/engine/messaging/impl/core/queue/QueueEntry;(WeightedRoundRobinQueueProvider.java:215)
   - locked <0x00000006c72c4328> (a com.sap.engine.messaging.impl.core.queue.Queue)
   - locked <0x00000006a5343140> (a com.sap.engine.messaging.impl.util.HashQueue)
   at com.sap.engine.messaging.impl.core.queue.Queue.run()V(Queue.java:1007)
   - locked <0x00000006a51d8ff0> (a com.sap.engine.messaging.impl.core.queue.provider.WeightedRoundRobinQueueProvider)
   at com.sap.engine.messaging.runtime.MSWorkWrapper.run()V(MSWorkWrapper.java:58)
   at com.sap.engine.core.thread.impl3.ActionObject.run()Ljava/lang/Object;(ActionObject.java:37)
   at java.security.AccessController.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;(Native Method)
   at com.sap.engine.core.thread.impl3.SingleThread.execute(Lcom/sap/engine/core/thread/ThreadContextImpl;)V(SingleThread.java:185)
   at com.sap.engine.core.thread.impl3.SingleThread.run()V(SingleThread.java:302)
     Locked ownable synchronizers:
   - None

SAP Process Integration

SAP NetWeaver

Logging, LoggingAPI, Tracing, Log, Performance, Scheduled, ToBeDelivered, To Be Delivered, Waiting, DispatchDisp, Dispatch, Messaging, Queue, Thread, WeightedRoundRobinQueueProvider, SAP, PI, Process Integration, PO, Process Orchestration, XI, 7.5, 7.4, 7.3, 7.31, 7.1 , KBA , BC-XI-CON-MSG , Messaging System , Problem