Description:
When debugging a performance problem in BW or any other application, sometimes we request the EMS to be setup to send client traces to the application with the problem. Note that it is really important to understand that client traces may be logged/written to the stderr/stdout when the method from the EMS API/EMS admin API has returned from its call when called from the application, so it is always advisable to check ems is performing well to guarantee that such API methods are not waiting for the ems to execute the actions that the method is intended to achieve. The following example is a BW project that intended to create a Queue reciever but that was noticing delays in the creation call.


***Time activity gets triggered****
2015 Nov 23 12:18:19:388 GMT +0100 BW.A085_READ_201TO400_COMPOSITE-RRServer_JMS_SR210_GetBusinessPartnerDetails-1 Debug [BW-Core]  => ProcessDefinitions/MainProcesses/RRServer_JMS_SR210_GetBusinessPartnerDetails.process/Get User Details>ProcessDefinitions/subProcesses/SR176_findWebUser.process/Get JMS Queue Message.eval(Job-17838235)
2015 Nov 23 12:18:19:388 GMT +0100 BW.A085_READ_201TO400_COMPOSITE-RRServer_JMS_SR210_GetBusinessPartnerDetails-1 Debug [BW-Core]  Get JMS Queue Message(Job-17838235) Input: <?xml version="1.0" encoding="UTF-8"?>
<ns0:ActivityInput xmlns:ns0="http://www.tibco.com/namespaces/tnt/plugins/jms">
    <destinationQueue>jms/SR176/FindWebUser/Reply/Queue</destinationQueue>
    <timeout>60</timeout>
    <selector>JMSCorrelationID='Id-f4f552564ab10000dbfc0c009c44c29f'</selector>
</ns0:ActivityInput>
***Time the API call to create consumer returned****
2015-11-23 12:18:27.293 [1694897032 JobCourier5] [TIBCO EMS]: [J] QueueSession Create QueueReceiver conn=901606401 sess=3658650139 cons=3975892525 dest=Queue[SR176.FindWebUser.Reply.Queue] type=Queue msgsel=[JMSCorrelationID='Id-f4f552564ab10000dbfc0c009c44c29f'] nolocal=false
2015 Nov 23 12:18:27:293 GMT +0100 BW.A085_READ_201TO400_COMPOSITE-RRServer_JMS_SR210_GetBusinessPartnerDetails-1 Debug [BW-Core]  <= ProcessDefinitions/MainProcesses/RRServer_JMS_SR210_GetBusinessPartnerDetails.process/Get User Details>ProcessDefinitions/subProcesses/SR176_findWebUser.process/Get JMS Queue Message.eval(Job-17838235) returned STAY_HERE
2015-11-23 12:18:27.294 [174223461 Thread-819] [TIBCO EMS]: [J] before ReceiveTimeout conn=901606401 sess=3658650139 cons=3975892525 timeout=60000
2015-11-23 12:18:27.299 [174223461 Thread-819] [TIBCO EMS]: [J] after ReceiveTimeout conn=901606401 sess=3658650139 cons=3975892525 timeout=60000 seqid=19871947864 msgid=ID:EMS-ESSENT-EXTERNAL1.7F7E562D3270D85F5A2A:1215347
2015-11-23 12:18:27.299 [174223461 Thread-819] [TIBCO EMS]: [J] Consumer Close conn=901606401 sess=3658650139 cons=3975892525
2015 Nov 23 12:18:27:607 GMT +0100 BW.A085_READ_201TO400_COMPOSITE-RRServer_JMS_SR210_GetBusinessPartnerDetails-1 Debug [BW-Core]  => ProcessDefinitions/MainProcesses/RRServer_JMS_SR210_GetBusinessPartnerDetails.process/Get User Details>ProcessDefinitions/subProcesses/SR176_findWebUser.process/Get JMS Queue Message.postEval(Job-17838235)
2015 Nov 23 12:18:27:607 GMT +0100 BW.A085_READ_201TO400_COMPOSITE-RRServer_JMS_SR210_GetBusinessPartnerDetails-1 Debug [BW-Core]  <= ProcessDefinitions/MainProcesses/RRServer_JMS_SR210_GetBusinessPartnerDetails.process/Get User Details>ProcessDefinitions/subProcesses/SR176_findWebUser.process/Get JMS Queue Message.postEval(Job-17838235) returned CONTINUE

It can be seen that the project was reaching the BW activity at 2015 Nov 23 12:18:19:388, yet the actual creation of the consumer based on the client trace occurred at 2015-11-23 12:18:27.293.

The above resulted in the engineers working on the service request thinking there was a problem with BW after it reached the activity. In reality, the API method for creating the consumer was executed shorty after the activity was triggered but the creation call method did not returned for eight seconds, which matches the client trace. Further investigation showed that EMS was using 100% CPU at the mentioned times and that the application was being impacted directly. The delays were a direct cause of the CPU usage by the EMS process. The behavior was observed as well by obtaining a thread dump of the BW process which shows the call to create consumer waiting.

Symptoms:
Performance problems on BW and EMS.

Cause:
EMS unresponsive due to high CPU usage.

Client traces on client application may be logged to stderr/stdout once the actual method/call for which the client trace is logging has returned.

Upgrade EMS server to a version that includes performance tuning options. The 8.1 release has the ability to increase the network I/O threads used by EMS. Add network_threads=3 to take advantage of the CPUs in the system and disable Hyperthreading.