Tuning Java Programs for Optimum MQ Get API Calls Performance

August 6, 2019 Roger Lacroix

You should really read this blog posting first.

The results of some of the test scenarios below, simply do not make any sense. I would like to think there is some sort of logic behind it but it is probably lack of testing by IBM that introduced some bugs in the code or should I say, ‘unexpected results’.

I’m going to repeat some of the information from the Tuning JMS blog posting, so that it will makes sense to people without having to jump back and forth between blog postings.

For each test run, I used the same 100 non-persistent MQRF2 (aka JMS) messages:

  • The first 25 messages are random sized messages between 735 bytes and 200KB
  • The next 25 messages are 8439 bytes in size
  • The next 24 messages are 735 bytes in size
  • The next 15 messages are 8439 bytes in size
  • The next 11 messages are 12298 bytes in size

    • A message consumer will not always receive the same sized message, hence, the first 25 messages are of a random size. The reason the latter 75 messages are in groups of same sized messages is because of something Steve Webb said in his post (IBM Developer question/answer) called MAXMSGL questions in regards to MQ JMS application. Near the bottom he said:

    If a number of smaller messages are then consumed, for example 10 messages at 5KB following on from the large message, the MQ-JMS classes will downsize the buffer to 5KB, and so on.

    I was curious when/what auto-resizing was going on. Hence, that is why I structured the last 75 messages the way I did.

    Now to the layout of MQ Auditor audit files. An MQ Auditor audit file is a simple CSV (Comma Separated Values) file, so you can load it into your spreadsheet program for easy viewing. Each API call is on a separate line in the audit file.
    i.e.
    {Date}{Time}{API Call}{PID}{TID}{CC}{RC}{UserId}{HConn}{MQ Structures}

    where

  • PID is Process Id
  • TID is Thread Id
  • CC is completion code
  • RC is reason code
  • HConn is the connection handle

    • Note: For MQGet API calls, after the MQ Structures are 2 important fields: BufferLength and DataLength. After the BufferLength and DataLength fields, there will be the internal headers (i.e. MQRFH2, MQIMS, etc.), if present, and the message data.

  • The BufferLength field is the length of the buffer used on the MQGet API call.
  • The DataLength field is the length of the message data returned in the buffer that was used on the MQGet API call.

    • Here is a sample MQGet API line from an MQ Auditor audit file with the BufferLength and DataLength fields highlighted.

    2019/08/02 16:06:54.320703, MQXF_GET , A, PID=12456, TID=1, CC=0, RC=0, UserId=tester, HConn=20971526, HObj=2, GMO_Options=MQGMO_NO_WAIT+MQGMO_BROWSE_NEXT+MQGMO_ACCEPT_TRUNCATED_MSG, GMO_WaitInterval=0, GMO_ResolvedQName=TEST.Q1, GMO_MatchOptions=MQMO_NONE, MD_PutDate=2019/08/03, MD_PutTime=00:19:08.00, MD_MsgId=414D51204D5141312020202020202020134CCD4020000B01, MD_Format=MQHRF2, MD_MsgType=MQMT_DATAGRAM, MD_Persistence=MQPER_NOT_PERSISTENT, BufferLength=256000, DataLength=725, RFH2_CCSID=437, RFH2_Encoding=273, RFH2_Format=MQSTR, RFH2_Folder1=jms_text , RFH2_Folder2=THis is a value for j1this is another value, RFH2_Folder3=This is a value for USR property U1 , MsgDataAsHex=496E204D515365726965732C20696E746572636F6D6D756E69,

    To set the baseline, I am going to be using the MQ sample program called amqsbcg.exe. I updated the BUFFERLENGTH define (line # 70) to be 256000 (from 65536) then compiled and linked the program. The reason I updated the define is because I don’t want to see reason code of 2079 (MQRC_TRUNCATED_MSG_ACCEPTED) for messages larger than 65536. It may confuse some people.

    Test #1:

  • Load the 100 MQRFH2 messages into a queue
  • Run amqsbcg in bindings mode against the same queue

    • Here is the MQ Auditor audit file. You can see that there are exactly 100 successful MQGets and 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE). This is exactly what is to be expected. If you scroll to the right of any MQGET line, you will see that in every case the size of the buffer given to MQ (BufferLength field) is 256000 bytes.

    For the MQ for Java program, I will be using one of my samples called MQTest12L.java. You can download the source code from here. The structure of the Java program is very similar to amqsbcg. It loops getting all messages until the queue is empty (it does not wait for more messages).

    I’m willing to bet that no one at IBM could correctly answer the following 2 questions for all 6 ‘MQ for Java’ test scenarios below!!
    (1) How many MQGets will be performed?
    (2) What will be the MQGET buffer length?

    I’m sure everyone reading this will say ‘that’s easy’ but I guarantee that after you read the 6 test scenarios, you will say WTF!!!

    Note: I’ll summarize the answers to the 2 questions above for the 8 ‘MQ for Java’ test scenarios at the end of the blog, so that you can re-iterate WTF!

    Test #2:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTest12L in bindings mode against the same queue
    • java MQTest12L -m MQWT2 -q TEST.Q1

    MQ Get Message Options set to the following:

    MQGetMessageOptions gmo = new MQGetMessageOptions();
gmo.options = CMQC.MQGMO_NO_WAIT + CMQC.MQGMO_FAIL_IF_QUIESCING;

    The loop for getting messages is (the abridged version):

    while(getMore)
{
   receiveMsg = new MQMessage();
   try
   {
      queue.get(receiveMsg, gmo);
   }
   catch (MQException e)
   {
      if ( (e.completionCode == CMQC.MQCC_FAILED) &&
           (e.reasonCode == CMQC.MQRC_NO_MSG_AVAILABLE) )
      {
         getMore = false;
      }
   }
}

    Here is the MQ Auditor audit file. You can see that there are a total of 111 MQGets:

  • 100 successful MQGets
  • 10 unsuccessful MQGet with RC of 2080 (MQRC_TRUNCATED_MSG_FAILED)
  • 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE)

    • This means that MQTest12L performed 10% more MQGets API calls than amqsbcg to accomplish the same thing. So, lets analyze why there were 10 unsuccessful MQGet with RC of 2080.

  • For the 1st MQGet API call, the internal JMQI routine allocated a 4096 byte buffer and the size of the message was 725 bytes
  • For the 2nd MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 4096 byte buffer but the message length was 4602 bytes. So, the internal JMQI routine allocated a new 4602 byte buffer and retrieve the message on the 3rd MQGet API call.
  • For the 4th, 10th, 12th, 14th, 21st and 31st MQGet API calls, they all failed with RC of 2080. For each occurrence, the internal JMQI routine allocates a new buffer of the size of the message that it failed to get.
  • On the 44th MQGet API call, for some unknown and very strange reason, the internal JMQI routine allocated a new buffer 4096 byte buffer. If you look closely, you will see that 44th MQGet is the 11th MQGet call with a smaller message size (8439 bytes) than what the internal JMQI routine had allocated for a buffer length (202601 bytes). Hence, the 44th MQGet API call failed with RC of 2080, because the internal JMQI routine was using a 4096 byte buffer but the message length was 8439 bytes. So, the internal JMQI routine allocated a new 8439 byte buffer and retrieve the message on the 44th MQGet API call.
  • On the 70th MQGet API call, for some unknown and very strange reason, the internal JMQI routine allocated a new buffer 4096 byte buffer. If you look closely, you will see that 70th MQGet is the 38th MQGet call with a smaller message size (725 bytes) than what the internal JMQI routine had allocated for a buffer length (8439 bytes). This is such strange behaviour.
  • For the 83rd MQGet API call, failed with RC of 2080 because the internal JMQI routine was using a 4096 byte buffer but the message length was 8439 bytes. So, the internal JMQI routine allocated a new 8439 byte buffer and retrieve the message on the 84th MQGet API call.
  • For the 99th MQGet API call, failed with RC of 2080 because the internal JMQI routine was using an 8439 byte buffer but the message length was 12286 bytes. So, the internal JMQI routine allocated a new 12286 byte buffer and retrieve the message on the 100th MQGet API call.

    • I have no idea what the internal JMQI routine is doing but it is very, very strange.

    Now, lets do the very same test again with MQTest12L program but add the com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable.

    Test #3:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTest12L in bindings mode with com.ibm.mq.jmqi.defaultMaxMsgSize set to 260000 against the same queue
    • java -Dcom.ibm.mq.jmqi.defaultMaxMsgSize=260000 MQTest12L -m MQWT2 -q TEST.Q1

    Here is the MQ Auditor audit file. You can see that there are exactly 100 successful MQGets and 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE). If you scroll to the right of any MQGET line, you will see that in every case the size of the buffer given to MQ (BufferLength field) is 260000 bytes.

    Test #4:

  • Load the 100 MQRFH2 messages into a queue
  • Set a message size of 254,000 on the MQQueue’s get method
  • Run MQTest12L in bindings mode against the same queue
    • java MQTest12L -m MQWT2 -q TEST.Q1

    MQQueue’s get method:

    queue.get(receiveMsg, gmo, 254000);

    The results are EXACTLY the same as test scenario #2. It makes no sense. The code is explicitly setting the value for the get method. Here is the MQ Auditor audit file. You can see that there are a total of 111 MQGets:

  • 100 successful MQGets
  • 10 unsuccessful MQGet with RC of 2080 (MQRC_TRUNCATED_MSG_FAILED)
  • 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE)

    • Test scenario #5 will be exactly the same as test scenario # 4 but add the com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable.

    Test #5:

  • Load the 100 MQRFH2 messages into a queue
  • Set a message size of 254,000 on the MQQueue’s get method
  • Run MQTest12L in bindings mode with com.ibm.mq.jmqi.defaultMaxMsgSize set to 260000 against the same queue
    • java -Dcom.ibm.mq.jmqi.defaultMaxMsgSize=260000 MQTest12L -m MQWT2 -q TEST.Q1

    Here is the MQ Auditor audit file. You can see that there are exactly 100 successful MQGets and 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE). If you scroll to the right of any MQGET line, you will see that in every case the size of the buffer given to MQ (BufferLength field) is 254000 bytes.

    This time the internal JMQI routine used the value set on the get call. Why? Why did it use it here and not for test scenario # 4?

    Now to “bake your noodle” (a Matrix reference), lets add MQGMO_ACCEPT_TRUNCATED_MSG to the MQ Get Message Options. Seriously, how can adding 1 option change the number of MQGETs and the buffer length ‘if’ the buffer length is larger than the message size!

    Test #6:

  • Load the 100 MQRFH2 messages into a queue
  • Set a message size of 254,000 on the MQQueue’s get method
  • Add MQGMO_ACCEPT_TRUNCATED_MSG to the MQGMO Options
  • Run MQTest12L in bindings mode against the same queue
    • java MQTest12L -m MQWT2 -q TEST.Q1

    MQ Get Message Options set to the following:

    MQGetMessageOptions gmo = new MQGetMessageOptions();
gmo.options = CMQC.MQGMO_NO_WAIT + CMQC.MQGMO_FAIL_IF_QUIESCING + CMQC.MQGMO_ACCEPT_TRUNCATED_MSG;

    MQQueue’s get method:

    queue.get(receiveMsg, gmo, 254000);

    For some unexplained reason the buffer length was set to 254000 for all MQGets which makes absolutely no sense. Why was the internal JMQI routine now honoring the setting of the MQGet size to 254000 but in test scenario #4 it was not?!?! The ONLY difference between test scenario #4 and #6 was that MQGMO option of MQGMO_ACCEPT_TRUNCATED_MSG was added.

    Here is the MQ Auditor audit file. You can see that there are a total of 111 MQGets:

  • 100 successful MQGets
  • 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE)

    • Test scenario #7 will be exactly the same as test scenario # 6 but add the com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable.

    Test #7:

  • Load the 100 MQRFH2 messages into a queue
  • Set a message size of 254,000 on the MQQueue’s get method
  • Add MQGMO_ACCEPT_TRUNCATED_MSG to the MQGMO Options
  • Run MQTest12L in bindings mode with com.ibm.mq.jmqi.defaultMaxMsgSize set to 260000 against the same queue
    • java -Dcom.ibm.mq.jmqi.defaultMaxMsgSize=260000 MQTest12L -m MQWT2 -q TEST.Q1

    Here is the MQ Auditor audit file. You can see that there are exactly 100 successful MQGets and 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE). If you scroll to the right of any MQGET line, you will see that in every case the size of the buffer given to MQ (BufferLength field) is 254000 bytes.

    This time the internal JMQI routine used the value set on the get call. Why? Why did it use it here and not for test scenario # 4? It is some truly weird stuff going on in the internal JMQI routine because it is not logical.

    Now time to turn UP the heat in the oven and REALLY bake that noodle!!! I’m going to redo Test scenarios #3 & #5 but lower the value of com.ibm.mq.jmqi.defaultMaxMsgSize to 55000.

    Test #8:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTest12L in bindings mode with com.ibm.mq.jmqi.defaultMaxMsgSize set to 55000 against the same queue
    • java -Dcom.ibm.mq.jmqi.defaultMaxMsgSize=55000 MQTest12L -m MQWT2 -q TEST.Q1

    Here is the MQ Auditor audit file. You can see that there are a total of 104 MQGets:

  • 100 successful MQGets
  • 3 unsuccessful MQGet with RC of 2080 (MQRC_TRUNCATED_MSG_FAILED)
  • 1 unsuccessful MQGet with RC of 2033 (MQRC_NO_MSG_AVAILABLE)

    • So, lets analyze why there were 3 unsuccessful MQGet with RC of 2080.

  • For the 1st MQGet API call, the internal JMQI routine allocated a 55000 byte buffer and the size of the message was 725 bytes
  • For the 10th MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 55000 byte buffer but the message length was 109471 bytes. So, the internal JMQI routine allocated a new 109471 byte buffer and retrieve the message on the 11th MQGet API call.
  • For the 17th MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 109471 byte buffer but the message length was 163730 bytes. So, the internal JMQI routine allocated a new 163730 byte buffer and retrieve the message on the 18th MQGet API call.
  • For the 27th MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 163730 byte buffer but the message length was 202601 bytes. So, the internal JMQI routine allocated a new 202601 byte buffer and retrieve the message on the 18th MQGet API call.

    • Now, lets do the very same test again as Test scenario #8 but explicitly set the MQQueue’s get buffer length to be 110000.

    Test #9:

  • Load the 100 MQRFH2 messages into a queue
  • Set a message size of 110000 on the MQQueue’s get method
  • Run MQTest12L in bindings mode with com.ibm.mq.jmqi.defaultMaxMsgSize set to 55000 against the same queue
    • java -Dcom.ibm.mq.jmqi.defaultMaxMsgSize=55000 MQTest12L -m MQWT2 -q TEST.Q1

    Here is the MQ Auditor audit file. You can see that there are a total of 104 MQGets:

  • 15 successful MQGets
  • 2 unsuccessful MQGet with RC of 2080 (MQRC_TRUNCATED_MSG_FAILED)

    • So, lets analyze why there were 2 unsuccessful MQGet with RC of 2080.

  • For the 1st MQGet API call, the internal JMQI routine allocated a 55000 byte buffer and the size of the message was 725 bytes
  • For the 10th MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 55000 byte buffer but the message length was 109471 bytes. So, the internal JMQI routine allocated a new 109471 byte buffer and retrieve the message on the 11th MQGet API call.
  • For the 17th MQGet API call, it failed with RC of 2080 because the internal JMQI routine was using a 109471 byte buffer but the message length was 163730 bytes. The internal JMQI routine does not allocate a new buffer because 163730 is above the specified MQQueue’s get specified buffer length of 110000.

    Here’s the summary of the test scenarios that I promised:

    Test Scenario com.ibm.mq.jmqi. defaultMaxMsgSize Application Buffer Length Specified on Get Used MQGMO-ACCEPT-TRUNCATED-MSG Number of MQGets Actual MQGet Buffer Length used
    #1 amqsbcg – 256000 No 101 256000
    #2 MQTest12L – – No 111 Initially 4096, adjusts up & down
    #3 MQTest12L 260000 – No 101 260000
    #4 MQTest12L – 254000 No 111 Initially 4096, adjusts up & down
    #5 MQTest12L 260000 254000 No 101 254000
    #6 MQTest12L – 254000 Yes 101 254000
    #7 MQTest12L 260000 254000 Yes 101 254000
    #8 MQTest12L 55000 – No 104 Initially 55000, adjusts up & down – never lower than 55000
    #9 MQTest12L 55000 110000 No 15 Initially 55000, adjusts up & down – never lower than 55000 and never above 110000

    There are so many things that are illogical.
    (1) Test scenario #4 should have been using a Buffer Length of 254000 that was specified on the get.
    (2) Why does adding the MQGMO option of MQGMO_ACCEPT_TRUNCATED_MSG change how the internal JMQI routine handle the gets? Test scenario #4 vs #6

    Final summary (maybe):

  • First thing you need to do is add the com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable to the run-time setup of your MQ Java program because it will keep the internal JMQI routine doing the right thing.
  • Second, com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable is ONLY used IF the application does not explicit set a buffer length on the MQQueue’s get method OR if com.ibm.mq.jmqi.defaultMaxMsgSize JVM environment variable is lower than the MQQueue’s get buffer length.
  • Third, pick a reasonable value for the JVM environment variable.
  • Fourth, the internal JMQI routine uses the JVM environment variable for BOTH JMS and non-JMS Java applications even though it is not documented anywhere!!
  • Fifth, maybe people should be implementing some sort of auditing/tracking system like MQ Auditor to understand what is going on under the covers of MQ because I most certainly have learned a few things over the last several days!!!

    • Update: Currently, the JVM environment variable ‘com.ibm.mq.jmqi.defaultMaxMsgSize’ is undocumented. Hence, the usage may change in a future release.

    Regards,
    Roger Lacroix
    Capitalware Inc.

    This entry was posted in IBM i (OS/400), IBM MQ, Java, Linux, macOS (Mac OS X), Programming, Unix, Windows, z/OS.

    Comments are closed.