Why is my java application doing multiple gets because the receive buffer is too small?

When investigating a MQ JMS performance problem, I noticed that there was a pattern of


followed by an MQGET with a bigger buffer which worked.

Being a performance person these double gets did not look right to me.

I spoke to Paul Titheridge of IBM who said this was fixed back in MQ V6 with a java property


If you specify

in the Java start-up you will get an 8KB buffer instead of the default 4KB.
Easy when you know how!

Showing what the C client is doing and how long it took.

I was asked to get involved in a dispute between the application team, and the MQ team about a slow C application running as a client. The application team felt it was MQ, the MQ team felt it was somewhere else. We had lots of feelings but no facts. I took a client trace, post processed it, and could point the finger of blame. I then spent more time digging into the trace and could see where the time is being spent.

Collecting a trace

We used strmqtrc -e -d 0 to turn on the trace. -d 0 says collect 0 length data buffers.
We ran the application and used endmqtrc -e to stop the trace
As we were on Linux we had to use the dspmqtrc *.TRC to format the trace. You may have lots of file on /var/mqm/trace. The trace of the client will have the userid associated with the application. Files with userid mqm come from the queue manager.

If you look at the trace file there is so much data is it temping to give up.
At the top of the file is a head and includes a line “Program Name :- …” so you can check this is the correct file.

The trace data looks like
20:41:03.511815 17291.5      :      { MQGET
20:41:03.511819 17291.5      :       -{ reqGetConn
20:41:03.511822 17291.5 RSESS:000007 -} reqGetConn rc=OK FunctionTime=3
20:41:03.511826 17291.5 RSESS:000007{ MQGET
  • 20:41:03.511815 is a time stamp
  • 17291.5 is processid.threadid
  • the 17291 is the same as the file name AMQ17291.0.FMT
  • {, -{,–{ shows the nesting level of the function so { is the top level, -{ is the next level deeper etc

Using the command
grep -e ” {” -e ” }” *291*.FMT|less
extracts just high level MQ API calls with the output from different threads intermixed

20:41:03.637143 17291.8 : } MQPUT rc=OK FunctionTime=874
20:41:03.637146 17291.8 : { MQGET
20:41:03.641930 17291.6 : } MQGET rc=OK FunctionTime=4784
20:41:03.641949 17291.6 : { MQPUT

If you look in the trace file near the entry times you will see the MQ control blocks, such as the MQMD, and MQOD so you can identify which queues are being used etc..

grep -e ” {” -e ” }” *291*.FMT| grep 17291.8 |less
shows you the high level data in the trace file for just the thread 8.

(1) 20:41:06.069828 17291.8 : { MQGET
(2) 20:41:06.105633 17291.8 : } MQGET rc=OK FunctionTime=6784
(3) 20:41:06.105656 17291.8 : { MQPUT
(4) 20:41:06.139679 17291.8 : } MQPUT rc=OK FunctionTime=482
(5) 20:41:06.953967 17291.8 : { MQGET

Note. The FunctionTime is often mis calculated and should be ignored.

  • The first MQGET took (2) – (1) 20:41:06.105633 – 20:41:06.069828 = 0.035806 seconds.
  • After the get to the following MQPUT it took (3) – (2) 20:41:06.105656 – 20:41:06.105633 = 0.000023 seconds.
  • The MQPUT took (4)-(3) 20:41:06.139679 – 20:41:06.105656 = 0.034023 seconds
  • After the MQPUT to the following MQGET (5) – (4) it took 20:41:06.953967 – 20:41:06.139679 = 0.814288 seconds

In summary the MQ requests took about 35 milliseconds, between the get and the put was 0.023 milliseconds, but between the put and the following get it took 814 milliseconds. This shows that most of the time was outside of MQ.

This was enough evidence to show the applications people to look else where.

Script to process the trace file and pull out the times in send and waiting for data

It is hard work extract the time stamps and calculating the time differences, so I wrote a simple Python script to do this for me.

This script gave me

(1) 20:41:04.400034 17291.6 : { MQPUT 0.000017
(2) 20:41:04.404946 17291.6 : } MQPUT 0.004912 sendTime 0.000960 waitTIme 0.003281
(3) 20:41:04.404949 17291.6 : { MQGET 0.000003
(4) 20:41:04.416523 17291.6 : } MQGET 0.011574 sendTime 0.000050 waitTIme 0.011167

(2) shows that the MQPUT took 0.004912 seconds, of which 0.000960 seconds was spent doing TCP send requests, and 0.003281 seconds was spent waiting for the request to be executed, and the response sent back. The message was large, so there were multiple send requests.
(3) shows the time between the end of the previous MQPUT, and the MQGET request was 0.000003 seconds.
(4) show the time of the MQGET . Overall it took 0.011574 seconds, of which 0.000050 was doing the send (there was only one send request), and 0.011167 seconds was spent waiting for the request to be executed, and the response sent back.

Digging deeper to see what is going on under the covers

Having a performance background I thought I would dig a bit deeper into this.

The overall picture I have is of getting to the airport. Do I take a taxi or take the bus?
It is usually better for everyone if people take the bus, because it is more efficient overall, and can reduce the amount of traffic. The journey may be a little longer because the bus has to stop to set down and pick up people. If you need to minimise the journey time, I would take a taxi. It may mean I get their faster than the bus – but it may not, if the taxi is queued behind the bus and cannot overtake.

The basic flow of a channel is
1. The application issues an MQ request
2. 1 or more TCP send requests pass the MQ verb and any data (such as message payload for an MQPUT). No more than 64 KB is sent per send request, so big messages will require multiple sends.
3. The last request includes the “end of data” flag.
4. The request is processed
5. The response and any data is sent back, a thread does one or more TCP receives to get the response and any data (for example the message payload for an MQGET request)
6. When all the data has been received, the request returns back to the application

For many years the application sent the data and blocked waiting for the response. If you had an application server, each thread had its own connection. This could lead to a very large number of connections. This configuration is called sharecnv(0)

With shared conversations introduced in MQ V7 there is one TCP connection and threads within a process can use it. The number of threads that can share it is defined with sharecnv(n).
The logic is very similar
1. The application issues an MQ request
2. The application does lock:TCP send:unlock. Multiple threads can send data, so you may get sends for multiple threads intermingled; send for thread 1, send for thread 2, send for thread 1, send for thread 3 etc..
3. The last request for the application request says “end of data”
4. The application thread is suspended.
5. There is a “reply thread” which issues the TCP receive requests.
6. When all the data has been returned for an application, the application thread is woken up.
This has the advantage that there may be only one connection, for multiple threads in the process.  This can be important if you have a very large number of threads using MQ.

With sharecnv(0) the channel was blocked during the MQ request.
There are two (or more) threads, one for sending, and a reply thread, means that asynchronous put, and asynchronous get can be supported.

How does the performance compare?

Sending data….

The TCP send request just passes the data into TCP buffers, so is quick. The TCP protocol says that after a number of bytes have been sent, TCP will wait till it has had confirmation that the earlier bytes have been received at the remote end. So looking at the TCP level you may have send(fast) send(fast) send(fast) send(slow – waiting for the ack from the far end), send (fast) send(slow)

This is the same for sharecnv(0) and sharecnv(> 0).

If you had sharecnv(0), so no sharing of the connection, the channel would do multiple sends, then perhaps do a database update. You may have other threads in the process also doing multiple sends and then perhaps a database update. If you did a packet trace of the network link you might see data for connection 1, data for connection 2, data for connection 1, data for connection 3 – just as for the sharecnv>0 case, but these requests may be done in parallel – depending on the configuration

So for sharecnv(0) and sharecnv(>0) you should expect similar send data rates.

Receiving data

The channels with sharecnv(0) have a dedicated connection. With sharecnv(>1) there is one reply connection shared by the users. With a low to medium throughput this should give the similar throughput as multiple channels with sharecnv(0). Because of the way the low level TCP protocol works, I can see that sometimes a channel defined with sharecnv(>1) may be faster!

With high throughput data may be delayed getting onto the shared connection, whereas with the sharecnv(0) channels the data can be flowing over connections in parallel.

What value should I use in sharecnv(n)

  1. If you want to use the new asynchronous functions, n must be greater than 0.
  2.  If you want the maximum possible throughput and minimum response time – at the cost of a larger number of connections then use n = 1.
  3.  If your throughput requirements are lower, and the applications can tolerate a small increase in response time then a larger n value will mean you need fewer connections – and so your queue manager can support more application instances.


What shape is your application splat?

There are a limited set of architectural patterns for MQ. I was working with Niels Simanis on how to identify them, and how to see if they change over time. Niels suggested the application splat gave a good visualization. The data behind it could be used by machine learning to tell if the pattern changes.

What are some typical application patterns?

1. Classic front end application MQCONN.. MQPUT, MQGET, .. MQDISC
2. Classic front end application with optimised application, MQCONN, n * ( MQPUT, MQGET ).. MQDISC
3. Classic back end MQCONN n * ( MQGET, MQPUT to different queues), MQDISC
4. Sender channel, MQGET, SEND, MQGET, SEND, MQGET SEND , ( Puts and gets to SYSTEM.CHANNEL.SYCNQ)
5. Receiver channel, RECEIVE, MQPUT, RECEIVE MQPUT, ( Puts and gets to SYSTEM.CHANNEL.SYCNQ)
6. Trigger monitor MQCONN N * (MQGET with BROWSE)

Within this we can have persistent message, non persistent messages; big message and small messages.

Some poor patterns which waste resources.

1. Do no work, MQCONN, MQDISC
2. The polling application ,MQPUT, n * (MQGET wait for 10 milliseconds)
3. The careless application for every MQGET , return code buffer too small, allocate bigger buffer, MQGET

What is a splat?

From the MQ accounting data , or the application trace (on Midrange) you can extract the statistics on the various MQ verbs
2. MQPUT of persistent messages
3. MQPUT of non persistent messages
4. MQPUT1 of persistent messages
5. MQPUT1 of non persistent messages
6. Successful MQGETS of persistent messages
7. Successul MQGETS of non persisttent messages
8. Successful MQGET with browse
9. Number of gets with non zero return code
10. Number of queues used for putting. For example putting to a clustered queue
11. Number of queues used for getting
12. Big puts > n KB
13. Small puts <= n KB
14. Big gets > n KB
15. Small gets <= n KB
17. MQCB

MQOPEN, MQCLOSE, MQINQ and MQSET could be added to the list to make it more complete.

You can take this data and create a radar or splat chart.


The graph looks like a paint ball has been splattered against a wall, or for the more refined, dropping a glass of red wine on a white carpet.

The data is normalized by dividing all the numbers by the sum of successful puts and gets (or 1 if there are no successful puts or gets).

What does this show us ?

We can make several observations from this chart

  1. It looks like there is a connect for every MQPUT – this gives scope for optimization
  2. Using MQPUT1 may be better than MQOPEN, MQPUT, MQCLOSE
  3. There is a high number of get errors.  In this case every message had RC 2080 – buffer too small.
  4. There were puts to multiple queues.   This was a clustered queue with two backends
  5. The size of the put message was > 4000 bytes.  The returned messages a mixture of sizes.  Some were > 4000 bytes, the remainder were below 4000 bytes.

With this splat graph it is easy to see if the applications are similar. For example
1. Are two business applications similar?
2. Has the shape of an application changed over time , either due to “improvements” or the workload changing.
3. You can have a “best practices profile” and see how different an application is from your the best practice profile.


Effects of application tuning


The application was tuned to use non persistent messages (as persistence was not needed) and do more work within MQCONN… MQDISC – leading to a reduction in MQCONNs.