Jmeter MQ GUI is working properly but cli summary showing error. Aggregate report shows different result

Hi I am new to Jmeter and I am trying to use Jmeter to do some performance testing on IBM MQ docker.

I have setup IBM MQ docker following this:

https://developer.ibm.com/tutorials/mq-connect-app-queue-manager-containers/

My apps can consume and publish to the broker so its working fine.

I am trying out Jmeter for performance testing and I have setup the Jmeter(5.6.2) with the jmx file provided following the pdf guide.

https://github.com/ibm-messaging/mqperf/tree/gh-pages/jmeter

After running the GUI, it seems working fine.

But when I run it in cli, it seem to be giving me errors. And the result seems weird by having more received msg than send. It could be due to retry but I am not sure. The following is the command I used:

jmeter.bat -n -t "C:\Users\alex\Desktop\all jmeter stuff\jmeter test plan jmx files\MQ-Sender-Receiver-Plan.jmx" -l "C:\Users\alex\Desktop\all jmeter stuff\jmeter test plan jmx files\results.jtl" -j "C:\Users\alex\Desktop\all jmeter stuff\jmeter test plan jmx files\log.jtl"

I have the cli logs here. Thanks in advance for any helps!

2023-07-12 18:28:32,787 INFO o.a.j.u.JMeterUtils: Setting Locale to en_EN
2023-07-12 18:28:32,799 INFO o.a.j.JMeter: Loading user properties from: user.properties
2023-07-12 18:28:32,799 INFO o.a.j.JMeter: Loading system properties from: system.properties
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: Copyright (c) 1998-2023 The Apache Software Foundation
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: Version 5.6.2
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: java.version=11.0.19
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: java.vm.name=Java HotSpot(TM) 64-Bit Server VM
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: os.name=Windows 10
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: os.arch=amd64
2023-07-12 18:28:32,804 INFO o.a.j.JMeter: os.version=10.0
2023-07-12 18:28:32,813 INFO o.a.j.JMeter: file.encoding=Cp1252
2023-07-12 18:28:32,813 INFO o.a.j.JMeter: java.awt.headless=true
2023-07-12 18:28:32,813 INFO o.a.j.JMeter: Max memory     =4294967296
2023-07-12 18:28:32,813 INFO o.a.j.JMeter: Available Processors =12
2023-07-12 18:28:32,818 INFO o.a.j.JMeter: Default Locale=English (EN)
2023-07-12 18:28:32,818 INFO o.a.j.JMeter: JMeter  Locale=English (EN)
2023-07-12 18:28:32,818 INFO o.a.j.JMeter: JMeterHome=C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2
2023-07-12 18:28:32,818 INFO o.a.j.JMeter: user.dir  =C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\bin
2023-07-12 18:28:32,818 INFO o.a.j.JMeter: PWD       =C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\bin
2023-07-12 18:28:32,819 INFO o.a.j.JMeter: IP: 202.188.100.169 Name: P_IFSLT2650 FullName: parkview-100-169.tm.net.my
2023-07-12 18:28:32,828 INFO o.a.j.s.FileServer: Default base='C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\bin'
2023-07-12 18:28:32,829 INFO o.a.j.s.FileServer: Set new base='C:\Users\alex\Desktop\all jmeter stuff\jmeter test plan jmx files'
2023-07-12 18:28:32,926 INFO o.a.j.s.SaveService: Testplan (JMX) version: 2.2. Testlog (JTL) version: 2.2
2023-07-12 18:28:32,941 INFO o.a.j.s.SaveService: Using SaveService properties version 5.0
2023-07-12 18:28:32,944 INFO o.a.j.s.SaveService: Using SaveService properties file encoding UTF-8
2023-07-12 18:28:32,946 INFO o.a.j.s.SaveService: Loading file: C:\Users\alex\Desktop\all jmeter stuff\jmeter test plan jmx files\MQ-Sender-Receiver-Plan_no_diode - Copy.jmx
2023-07-12 18:28:33,010 INFO o.a.j.JMeter: Creating summariser <summary>
2023-07-12 18:28:33,020 INFO o.a.j.e.StandardJMeterEngine: Running the test!
2023-07-12 18:28:33,021 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2023-07-12 18:28:33,021 INFO o.a.j.s.SampleEvent: List of sample_variables: []
2023-07-12 18:28:33,028 INFO o.a.j.e.u.CompoundVariable: Note: Function class names must contain the string: '.functions.'
2023-07-12 18:28:33,028 INFO o.a.j.e.u.CompoundVariable: Note: Function class names must not contain the string: '.gui.'
2023-07-12 18:28:33,225 INFO o.a.j.t.TestPlan: added C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\lib\mqjars\com.ibm.mq.allclient.jar to classpath
2023-07-12 18:28:33,225 INFO o.a.j.t.TestPlan: added C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\lib\mqjars\jms.jar to classpath
2023-07-12 18:28:33,226 INFO o.a.j.t.TestPlan: added C:\Users\alex\Desktop\all jmeter stuff\apache-jmeter-5.6.2\lib\mqjars\org.json.jar to classpath
2023-07-12 18:28:33,434 INFO o.a.j.JMeter: Running test (1689157713434)
2023-07-12 18:28:33,435 INFO o.a.j.e.StandardJMeterEngine: Starting setUp thread groups
2023-07-12 18:28:33,435 INFO o.a.j.e.StandardJMeterEngine: Starting setUp ThreadGroup: 1 : setUp  Thread Group (Sender Connections) 
2023-07-12 18:28:33,435 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group setUp  Thread Group (Sender Connections).
2023-07-12 18:28:33,435 INFO o.a.j.e.StandardJMeterEngine: Test will stop abruptly on error
2023-07-12 18:28:33,435 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:28:33,438 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2023-07-12 18:28:33,438 INFO o.a.j.e.StandardJMeterEngine: Starting setUp ThreadGroup: 2 : setUp Thread Group (Receiver Connections) 
2023-07-12 18:28:33,438 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group setUp Thread Group (Receiver Connections).
2023-07-12 18:28:33,438 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2023-07-12 18:28:33,438 INFO o.a.j.t.ThreadGroup: Starting thread group... number=2 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:28:33,440 INFO o.a.j.t.ThreadGroup: Started thread group number 2
2023-07-12 18:28:33,441 INFO o.a.j.e.StandardJMeterEngine: Waiting for all setup thread groups to exit
2023-07-12 18:28:33,444 INFO o.a.j.t.JMeterThread: Thread started: setUp Thread Group (Receiver Connections) 2-1
2023-07-12 18:28:33,444 INFO o.a.j.t.JMeterThread: Thread started: setUp  Thread Group (Sender Connections) 1-1
2023-07-12 18:28:33,446 INFO o.a.j.s.SampleResult: Note: Sample TimeStamps are START times
2023-07-12 18:28:33,446 INFO o.a.j.s.SampleResult: sampleresult.default.encoding is set to UTF-8
2023-07-12 18:28:33,446 INFO o.a.j.s.SampleResult: sampleresult.useNanoTime=true
2023-07-12 18:28:33,446 INFO o.a.j.s.SampleResult: sampleresult.nanoThreadSleep=5000
2023-07-12 18:28:34,740 INFO o.a.j.p.j.s.J.Create Sender Connections to Queue Manager: ####### Sender connection #0 to queue manager QM1 established.
2023-07-12 18:28:34,740 INFO o.a.j.p.j.s.J.Create Receiver Connections to Queue Manager: ####### Receiver connection #0 to queue manager QM1 established.
2023-07-12 18:28:34,752 INFO o.a.j.t.JMeterThread: Thread is done: setUp  Thread Group (Sender Connections) 1-1
2023-07-12 18:28:34,752 INFO o.a.j.t.JMeterThread: Thread finished: setUp  Thread Group (Sender Connections) 1-1
2023-07-12 18:28:34,753 INFO o.a.j.r.Summariser: summary +      1 in 00:00:01 =    0.8/s Avg:  1303 Min:  1303 Max:  1303 Err:     0 (0.00%) Active: 1 Started: 2 Finished: 1
2023-07-12 18:28:34,753 INFO o.a.j.t.JMeterThread: Thread is done: setUp Thread Group (Receiver Connections) 2-1
2023-07-12 18:28:34,753 INFO o.a.j.t.JMeterThread: Thread finished: setUp Thread Group (Receiver Connections) 2-1
2023-07-12 18:28:34,754 INFO o.a.j.e.StandardJMeterEngine: All Setup Threads have ended
2023-07-12 18:28:34,770 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 1 : Senders
2023-07-12 18:28:34,770 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group Senders.
2023-07-12 18:28:34,770 INFO o.a.j.e.StandardJMeterEngine: Test will stop abruptly on error
2023-07-12 18:28:34,770 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:28:34,771 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2023-07-12 18:28:34,771 INFO o.a.j.e.StandardJMeterEngine: Starting ThreadGroup: 2 : Receivers
2023-07-12 18:28:34,771 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group Receivers.
2023-07-12 18:28:34,771 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2023-07-12 18:28:34,771 INFO o.a.j.t.ThreadGroup: Starting thread group... number=2 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:28:34,772 INFO o.a.j.t.JMeterThread: Thread started: Senders 1-1
2023-07-12 18:28:34,772 INFO o.a.j.t.ThreadGroup: Started thread group number 2
2023-07-12 18:28:34,772 INFO o.a.j.e.StandardJMeterEngine: All thread groups have been started
2023-07-12 18:28:34,773 INFO o.a.j.t.JMeterThread: Thread started: Receivers 2-1
2023-07-12 18:29:00,002 INFO o.a.j.r.Summariser: summary +   4986 in 00:00:25 =  197.5/s Avg:     2 Min:     1 Max:  1303 Err:     0 (0.00%) Active: 2 Started: 2 Finished: 0
2023-07-12 18:29:00,003 INFO o.a.j.r.Summariser: summary =   4987 in 00:00:27 =  187.7/s Avg:     3 Min:     1 Max:  1303 Err:     0 (0.00%)
2023-07-12 18:29:30,002 INFO o.a.j.r.Summariser: summary +   6000 in 00:00:30 =  200.0/s Avg:     2 Min:     1 Max:     9 Err:     0 (0.00%) Active: 2 Started: 2 Finished: 0
2023-07-12 18:29:30,003 INFO o.a.j.r.Summariser: summary =  10987 in 00:00:57 =  194.2/s Avg:     2 Min:     1 Max:  1303 Err:     0 (0.00%)
2023-07-12 18:29:34,771 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: Senders 1-1
2023-07-12 18:29:34,772 INFO o.a.j.t.JMeterThread: Thread finished: Senders 1-1
2023-07-12 18:29:39,809 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:29:44,823 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:29:49,837 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:29:54,852 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:29:59,870 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:04,886 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:04,886 INFO o.a.j.r.Summariser: summary +    961 in 00:00:35 =   27.5/s Avg:    33 Min:     1 Max:  5031 Err:     6 (0.62%) Active: 1 Started: 2 Finished: 1
2023-07-12 18:30:04,888 INFO o.a.j.r.Summariser: summary =  11948 in 00:01:31 =  130.6/s Avg:     5 Min:     1 Max:  5031 Err:     6 (0.05%)
2023-07-12 18:30:09,903 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:14,915 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:19,929 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:24,946 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:29,961 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:34,982 INFO o.a.j.p.j.s.J.Receive Messages: ############ consumer.receive timed out (timeout value: 5000)
2023-07-12 18:30:34,983 INFO o.a.j.r.Summariser: summary +      6 in 00:00:30 =    0.2/s Avg:  5015 Min:  5012 Max:  5020 Err:     6 (100.00%) Active: 1 Started: 2 Finished: 1
2023-07-12 18:30:34,984 INFO o.a.j.r.Summariser: summary =  11954 in 00:02:02 =   98.3/s Avg:     7 Min:     1 Max:  5031 Err:    12 (0.10%)
2023-07-12 18:30:34,985 INFO o.a.j.t.JMeterThread: Stopping because end time detected by thread: Receivers 2-1
2023-07-12 18:30:34,986 INFO o.a.j.t.JMeterThread: Thread finished: Receivers 2-1
2023-07-12 18:30:34,986 INFO o.a.j.e.StandardJMeterEngine: Starting tearDown thread groups
2023-07-12 18:30:34,986 INFO o.a.j.e.StandardJMeterEngine: Starting tearDown ThreadGroup: 1 : tearDown Thread Group (Sender Connections)
2023-07-12 18:30:34,986 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group tearDown Thread Group (Sender Connections).
2023-07-12 18:30:34,986 INFO o.a.j.e.StandardJMeterEngine: Test will stop abruptly on error
2023-07-12 18:30:34,987 INFO o.a.j.t.ThreadGroup: Starting thread group... number=1 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:30:34,989 INFO o.a.j.t.ThreadGroup: Started thread group number 1
2023-07-12 18:30:34,989 INFO o.a.j.e.StandardJMeterEngine: Starting tearDown ThreadGroup: 2 : tearDown Thread Group (Receiver Connections)
2023-07-12 18:30:34,989 INFO o.a.j.e.StandardJMeterEngine: Starting 1 threads for group tearDown Thread Group (Receiver Connections).
2023-07-12 18:30:34,990 INFO o.a.j.e.StandardJMeterEngine: Thread will continue on error
2023-07-12 18:30:34,990 INFO o.a.j.t.ThreadGroup: Starting thread group... number=2 threads=1 ramp-up=1 delayedStart=false
2023-07-12 18:30:34,990 INFO o.a.j.t.JMeterThread: Thread started: tearDown Thread Group (Sender Connections) 1-1
2023-07-12 18:30:34,991 INFO o.a.j.t.ThreadGroup: Started thread group number 2
2023-07-12 18:30:34,991 INFO o.a.j.t.JMeterThread: Thread started: tearDown Thread Group (Receiver Connections) 2-1
2023-07-12 18:30:35,042 INFO o.a.j.p.j.s.J.Close Receiver Connections: ###### Receiver Connection Closed
2023-07-12 18:30:35,042 INFO o.a.j.p.j.s.J.Close Sender Connections: ###### Sender Connection closed
2023-07-12 18:30:35,043 INFO o.a.j.t.JMeterThread: Thread is done: tearDown Thread Group (Sender Connections) 1-1
2023-07-12 18:30:35,043 INFO o.a.j.t.JMeterThread: Thread is done: tearDown Thread Group (Receiver Connections) 2-1
2023-07-12 18:30:35,043 INFO o.a.j.t.JMeterThread: Thread finished: tearDown Thread Group (Sender Connections) 1-1
2023-07-12 18:30:35,043 INFO o.a.j.t.JMeterThread: Thread finished: tearDown Thread Group (Receiver Connections) 2-1
2023-07-12 18:30:35,043 INFO o.a.j.e.StandardJMeterEngine: Notifying test listeners of end of test
2023-07-12 18:30:35,048 INFO o.a.j.r.Summariser: summary +      2 in 00:00:00 =   30.8/s Avg:    50 Min:    49 Max:    51 Err:     0 (0.00%) Active: 0 Started: 2 Finished: 2
2023-07-12 18:30:35,049 INFO o.a.j.r.Summariser: summary =  11956 in 00:02:02 =   98.3/s Avg:     7 Min:     1 Max:  5031 Err:    12 (0.10%)

Solution

Looking into the code:

def consumer=vars.getObject("Consumer");
def session=vars.getObject("ReceiverSession")
 
def msg = consumer.receive("${receive_timeout}" as Integer) 

if(msg!=null) {
    if("${transacted}".equals("true")) session.commit()
    
    log.debug("########### Message Received"+msg)

    SampleResult.setResponseData(msg.toString())
    SampleResult.setDataType(org.apache.jmeter.samplers.SampleResult.TEXT)
} else {
    log.info("############ consumer.receive timed out (timeout value: " + "${receive_timeout}" + ")")
    //Mark timeout as 'error' to enable filtering out in listeners (to just analyse successful receive rate etc)
    SampleResult.setSuccessful(false)
}

it appears that you will get the following error:

############ consumer.receive timed out (timeout value: 5000)

when the receiver thread fails to retrieve the message withing 5 seconds timeout.

So first thing I would check is your MQ broker container logs

In general JMeter in non-GUI mode has much better performance than in GUI mode so it might be the case it just overloads your MQ broker instance and it cannot properly respond on message receive requests.

Apart from checking the logs you can additionally ensure that the broker has enough headroom to operate in terms of CPU, RAM, Network, Disk, etc. It can be done using container monitoring solution like docker stats or JMeter PerfMon Plugin. If this is the case you might need to increase container limits or Docker engine