JMS and Java Client Mode Performance Issues for MQ Get API Calls

August 15, 2019 Roger Lacroix

I’ve wasted far, far too much of my time inspecting what is going on with the auto-resizing of the get buffer for the internal JMQI and MQI components for MQ classes for JMS, MQ classes for Java and MQ classes for .NET.

A strange entry in one of the MQ Auditor audit files got my attention. So, I thought I would test MQ classes for JMS and MQ classes for Java in client mode WITHOUT any JVM environment variables because this is how most of the world would be using their applications.

For the test set of messages used and the MQ Auditor audit file layout (in particular the BufferLength and DataLength fields), please review the information from one of the previous blog postings.

I’m going to be using MQTest12L.java and MQTestJMS12L.java which are the same programs I used in my previous tests. All 4 tests will be in client mode: 2 for MQTest12L.java and 2 for MQTestJMS12L.java.

Test #1: MQTest12L.java client mode – MQGMO No Wait:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTest12L in client mode against the same queue
    • java MQTest12L -m MQWT2 -q TEST.Q1 -h 127.0.0.1 -p 1416 -c TEST.CHL -u tester -x mypwd

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

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

    • There are 3 instances of weird behavior:

  • At line # 22 in the audit file, you will see a successful MQGet with the parameters “BufferLength=19754, DataLength=19754”
  • At line # 23 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=19754, DataLength=109471”. So, the internal JMQI component is suppose to allocate a new larger buffer of 109471 and issue the MQGet call again.
  • At line # 24 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=23048, DataLength=109471”. Clearly, something went wrong because the new buffer used was wrong. The new buffer size for the second MQGet was suppose to be 109471 but it was 23048.
  • At line # 25 in the audit file, the MQGet is successful. It took 3 MQGet calls and 2 buffer re-allocations to get it right.
  • This happens again on lines # 31, 32 & 33 of the audit file
  • This happens again on lines # 42, 43 & 44 of the audit file

    • Test #2: MQTest12JMSL.java client mode – MQGMO No Wait:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTestJMS12L in client mode against the same queue
    • java MQTest12JMSL -m MQWT2 -q TEST.Q1 -h 127.0.0.1 -p 1416 -c TEST.CHL -u tester -x mypwd

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

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

    • There are 8 instances of weird behavior:

  • At line # 10 in the audit file, you will see a successful MQGet with the parameters “BufferLength=2568, DataLength=725”. Notice how it did NOT start with a 4KB. Another strange oddity.
  • At line # 11 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=2568, DataLength=4602”. So, the internal JMQI component is suppose to allocate a new larger buffer of 4602 and issue the MQGet call again.
  • At line # 12 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=4096, DataLength=4602”. Clearly, something went wrong because the new buffer used was wrong. The new buffer size for the second MQGet was suppose to be 4602 but it was 4096.
  • At line # 13 in the audit file, the MQGet is successful. It took 3 MQGet calls and 2 buffer re-allocations to get it right.
  • This happens again on lines # 14, 15 & 16 of the audit file
  • This happens again on lines # 21, 22 & 23 of the audit file
  • This happens again on lines # 24, 25 & 26 of the audit file
  • This happens again on lines # 27, 28 & 29 of the audit file
  • This happens again on lines # 35, 36 & 37 of the audit file
  • This happens again on lines # 46, 47 & 48 of the audit file

    • Test #3: MQTest12L.java client mode – MQGMO 100ms Wait:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTest12L in client mode against the same queue
    • java MQTest12L -m MQWT2 -q TEST.Q1 -h 127.0.0.1 -p 1416 -c TEST.CHL -u tester -x mypwd

    Here is the MQ Auditor audit file. You can see that there are a total of 14 MQGets and 100 MQCallBacks:

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

    • There are 3 instances of weird behavior:

  • At line # 43 in the audit file, the MQCallBack fails with RC of 2080 (parameters “CBC_BufferLength=110592, CBC_DataLength=109471”) because the previous MQCB call set the buffer size to 19754. So, the internal JMQI component is suppose to allocate a new larger buffer of 109471 and issue the MQGet call again.
  • At line # 45 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=23048, DataLength=109471”. Clearly, something went wrong because the new buffer used was wrong. The new buffer size for the this MQGet was suppose to be 109471 but it was 23048.
  • At line # 46 in the audit file, the MQGet is successful. It took 1 MQCallBack and 2 MQGet calls and 2 buffer re-allocations to get it right.
  • This happens again on lines # 63, 65 & 66 of the audit file
  • This happens again on lines # 92, 94 & 95 of the audit file

    • Test #4: MQTest12JMSL.java client mode – MQGMO 100ms Wait:

  • Load the 100 MQRFH2 messages into a queue
  • Run MQTestJMS12L in client mode against the same queue
    • java MQTest12JMSL -m MQWT2 -q TEST.Q1 -h 127.0.0.1 -p 1416 -c TEST.CHL -u tester -x mypwd

    Here is the MQ Auditor audit file. You can see that there are a total of 18 MQGets and 100 MQCallBacks:

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

    • There are 7 instances of weird behavior:

  • At line # 15 in the audit file, the MQCallBack fails with RC of 2080 (parameters “CBC_BufferLength=8192, CBC_DataLength=4602”) because the previous MQCB call set the buffer size to 4096. So, the internal JMQI component is suppose to allocate a new larger buffer of 4602 and issue the MQGet call again.
  • At line # 45 in the audit file, the MQGet fails with RC of 2080 with the parameters “BufferLength=2568, DataLength=4602”. Clearly, something went wrong because the new buffer used was wrong. The new buffer size for the this MQGet was suppose to be 4602 but it was 2568.
  • At line # 46 in the audit file, the MQGet is successful. It took 1 MQCallBack and 2 MQGet calls and 2 buffer re-allocations to get it right.
  • This happens again on lines # 20, 22 & 23 of the audit file
  • This happens again on lines # 37, 39 & 40 of the audit file
  • This happens again on lines # 42, 44 & 45 of the audit file
  • This happens again on lines # 47, 49 & 50 of the audit file
  • This happens again on lines # 67, 69 & 70 of the audit file
  • This happens again on lines # 96, 98 & 99 of the audit file

    • So, is the internal JMQI component working as designed for auto-resizing of the buffer? Clearly not. But then again, since there is no documentation on it, so who knows.

    I thought it was bad when the internal JMQI component was doing 2 MQGets for each application issued MQGet but 3 is just getting ridiculous.

    Regards,
    Roger Lacroix
    Capitalware Inc.

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

    Comments are closed.