Bug 53357 - JMS Point to Point reports too high response times in Request Response Mode
JMS Point to Point reports too high response times in Request Response Mode
Status: RESOLVED FIXED
Product: JMeter
Classification: Unclassified
Component: Main
2.7
All All
: P2 major (vote)
: ---
Assigned To: JMeter issues mailing list
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2012-06-04 20:13 UTC by Philippe Mouawad
Modified: 2012-06-16 12:59 UTC (History)
1 user (show)



Attachments
Test Plan (5.85 KB, application/octet-stream)
2012-06-04 20:13 UTC, Philippe Mouawad
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Philippe Mouawad 2012-06-04 20:13:03 UTC
Created attachment 28882 [details]
Test Plan

I configured a very simple Test plan with a JMS Point-to-Point where Request queue and Receive Queue are the same.
If I run 3 samples, randomly I can get one response time equal to Timeout while receive was in fact immediate.

I added logs around wait in FixedQueueExecutor and notify in MessageAdmin.


Here is the result:
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: wait for reply Milamber-1338839705293 started on 1338839705298 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: GU Point-à-Point 1-1 will wait on : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: RPL_ID [Milamber-1338839705293] for holder request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287}, reply=null 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notifying : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notified : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: done waiting for Milamber-1338839705293 on ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287} ended on 1338839705320 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GET_ID [Milamber-1338839705293] for request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705287}, reply=ActiveMQTextMessage {commandId = 5, responseRequired = true, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:1, originalDestination = null, originalTransactionId = null, producerId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705294, arrival = 0, brokerInTime = 1338839705294, brokerOutTime = 1338839705295, correlationId = Milamber-1338839705293, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text = Message de test
ID TEMPS = 1338839705287} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: REQ_ID [Milamber-1338839705328] 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: RPL_ID [Milamber-1338839705328] for holder request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328}, reply=null 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notifying : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notified : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328} 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: wait for reply Milamber-1338839705328 started on 1338839705353 
2012/06/04 21:55:05 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: GU Point-à-Point 1-1 will wait on : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328} 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: done waiting for Milamber-1338839705328 on ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328} ended on 1338839725353 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GET_ID [Milamber-1338839705328] for request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839705328}, reply=ActiveMQTextMessage {commandId = 6, responseRequired = true, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:2, originalDestination = null, originalTransactionId = null, producerId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839705328, arrival = 0, brokerInTime = 1338839705329, brokerOutTime = 1338839705329, correlationId = Milamber-1338839705328, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text = Message de test
ID TEMPS = 1338839705328} 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.Utils: Adding property [JMSCorrelationId=Milamber-1338839725355] 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: REQ_ID [Milamber-1338839725355] 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: RPL_ID [Milamber-1338839725355] for holder request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355}, reply=null 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notifying : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355} 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: wait for reply Milamber-1338839725355 started on 1338839725358 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GU Point-à-Point 1-1-JMS-Receiver notified : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355} 
2012/06/04 21:55:25 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: GU Point-à-Point 1-1 will wait on : ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355} 
2012/06/04 21:55:45 DEBUG - jmeter.protocol.jms.sampler.FixedQueueExecutor: done waiting for Milamber-1338839725355 on ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355} ended on 1338839745358 
2012/06/04 21:55:45 DEBUG - jmeter.protocol.jms.sampler.MessageAdmin: GET_ID [Milamber-1338839725355] for request=ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = null, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody = false, droppable = false, text = Message de test
ID TEMPS = 1338839725355}, reply=ActiveMQTextMessage {commandId = 7, responseRequired = true, messageId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1:3, originalDestination = null, originalTransactionId = null, producerId = ID:macbook-pro-de-philippe-mouawad.local-64635-1338839705124-0:2:1:1, destination = queue://example.A, transactionId = null, expiration = 0, timestamp = 1338839725356, arrival = 0, brokerInTime = 1338839725356, brokerOutTime = 1338839725357, correlationId = Milamber-1338839725355, replyTo = queue://example.A, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text = Message de test
ID TEMPS = 1338839725355} 
2012/06/04 21:55:45 INFO  - jmeter.threads.JMeterThread: Thread finished: GU Point-à-Point 1-1
Comment 1 Philippe Mouawad 2012-06-04 20:13:30 UTC
Issue is due to notify happening before wait has started.
Comment 2 Philippe Mouawad 2012-06-04 20:18:15 UTC
Date: Mon Jun  4 20:17:31 2012
New Revision: 1346144

URL: http://svn.apache.org/viewvc?rev=1346144&view=rev
Log:
Bug 53357 - JMS Point to Point reports too high response times in Request Response Mode

Modified:
   jmeter/trunk/src/protocol/jms/org/apache/jmeter/protocol/jms/sampler/FixedQueueExecutor.java
   jmeter/trunk/src/protocol/jms/org/apache/jmeter/protocol/jms/sampler/MessageAdmin.java
   jmeter/trunk/xdocs/changes.xml
Comment 3 Sebb 2012-06-16 12:59:13 UTC
URL: http://svn.apache.org/viewvc?rev=1350918&view=rev
Log:
JMS Point to Point reports too high response times in Request Response Mode
- ensure the timeout is actually used
Bugzilla Id: 53357