APAR status
Closed as program error.
Error description
An application which uses the MQ classes for JMS is initiated in a J2SE environment, where multiple threads are started in parallel, each thread running within a separate Java ClassLoader. When trace is enabled, it is observed that the MQ classes for JMS application hangs, and a Java thread dump collected when the system is in this state shows the following thread stacks: Numerous threads with the stack: at java/util/logging/FileHandler.publish(FileHandler.java:709) (entered lock: java/util/logging/FileHandler@0x00000000FFFB1860, entry count: 1) at java/util/logging/Logger.log(Logger.java:749) at java/util/logging/Logger.doLog(Logger.java:776) at java/util/logging/Logger.logp(Logger.java:996) at com/ibm/msg/client/commonservices/j2se/trace/DefaultTracer.trace Data(DefaultTracer.java:355) at com/ibm/msg/client/commonservices/trace/Trace.traceDataInternal( Trace.java:1266) at com/ibm/msg/client/commonservices/trace/Trace.traceData(Trace.ja va:1065) at com/ibm/msg/client/commonservices/trace/Trace.setOn(Trace.java:5 96) (entered lock: com/ibm/msg/client/commonservices/trace/Trace@0x00000000E01B5910 , entry count: 1) at com/ibm/msg/client/commonservices/trace/Trace.initialize(Trace.j ava:2521) at com/ibm/msg/client/commonservices/CommonServices.<clinit>(Common Services.java:123) at com/ibm/msg/client/commonservices/propertystore/PropertyStore.in itialize(PropertyStore.java:545) at com/ibm/msg/client/commonservices/propertystore/PropertyStore.<c linit>(PropertyStore.java:254) at com/ibm/msg/client/commonservices/trace/Trace.<clinit>(Trace.jav a:548) at com/ibm/msg/client/jms/internal/JmsReadablePropertyContextImpl.< clinit>(JmsReadablePropertyContextImpl.java:51) ... ... ... A single thread with the stack: Waiting on: java/lang/J9VMInternals$ClassInitializationLock@0x00000000E00B3A 88 Owned by: <unowned> Heap bytes allocated since last GC cycle=45112 (0xB038) Java callstack: at com/ibm/msg/client/commonservices/trace/TableBuilder.<clinit>(Ta bleBuilder.java:106) at com/ibm/msg/client/commonservices/j2se/trace/HumanFormatter.writ eHeaderInfo(HumanFormatter.java:159) at com/ibm/msg/client/commonservices/j2se/trace/HumanFormatter.form at(HumanFormatter.java:285) at java/util/logging/StreamHandler.publish(StreamHandler.java:222) (entered lock: java/util/logging/FileHandler@0x00000000FFFB1860,entry count: 2) at java/util/logging/FileHandler.publish(FileHandler.java:712) (entered lock: java/util/logging/FileHandler@0x00000000FFFB1860,entry count: 1) at java/util/logging/Logger.log(Logger.java:749) at java/util/logging/Logger.doLog(Logger.java:776) at java/util/logging/Logger.logp(Logger.java:996) at com/ibm/msg/client/commonservices/j2se/trace/DefaultTracer.trace Data(DefaultTracer.java:355) at com/ibm/msg/client/commonservices/trace/Trace.traceDataInternal( Trace.java:1266) at com/ibm/msg/client/commonservices/trace/Trace.traceData(Trace.ja va:1065) at com/ibm/msg/client/commonservices/trace/Trace.setOn(Trace.java:5 96) (entered lock: com/ibm/msg/client/commonservices/trace/Trace@0x00000000E01B4A10 , entry count: 1) at com/ibm/msg/client/commonservices/trace/Trace.initialize(Trace.j ava:2521) at com/ibm/msg/client/commonservices/CommonServices.<clinit>(Common Services.java:123) at com/ibm/msg/client/commonservices/propertystore/PropertyStore.in itialize(PropertyStore.java:545) at com/ibm/msg/client/commonservices/propertystore/PropertyStore.<c linit>(PropertyStore.java:254) at com/ibm/msg/client/commonservices/trace/Trace.<clinit>(Trace.jav a:548) at com/ibm/msg/client/jms/internal/JmsReadablePropertyContextImpl.< clinit>(JmsReadablePropertyContextImpl.java:51) ... ... ...
Local fix
Problem summary
**************************************************************** USERS AFFECTED: This issue affects users of the IBM MQ classes for Java, classes for JMS and IBM MQ resource adapter, who are running in an environment with trace enabled, with multiple threads accessing the MQ classes for Java/JMS running under separate Java ClassLoaders, which are started simultaneously. This does not include users of WebSphere Application Server traditional, where the MQ classes for Java, classes for JMS and resource adapter trace is integrated into the application server tracing mechanism. Platforms affected: MultiPlatform **************************************************************** PROBLEM DESCRIPTION: When multiple threads are started simultaneously which interact with the IBM MQ classes for Java, classes for JMS and resource adapter, and trace is enabled, the classes use object locks to prevent multiple threads from initialising the same "java.util.logging.Logger" object simultaneously, which is used to manage the trace output. Trace initialisation is generally performed when the class is loaded by the thread's ClassLoader, as the classes contain static initializer blocks which configure the system for tracing when the class is first loaded. For example, a JMS application thread might first reference a "com.ibm.mq.jms.MQConnectionFactory" class, with the syntax: MQConnectionFactory myCF = new MQConnectionFactory(); If trace is enabled in this scenario, then a "java.util.logging.Logger" object is instantiated, which is then configured for tracing using the application thread. If other threads are started simultaneously, they will block until the first thread has completed the trace initialisation - with the end result being that the other threads will then use the same Logger so that trace output from all of the threads ends up in the same trace file. However, if each thread was running under their own separate Java ClassLoader, and each ClassLoader's parent ClassLoader is the one which loads the JRE's class "java.util.logging.Logger", the object locking model would not prevent each thread from attempting to configure the same "java.util.logging.Logger" object instance in parallel. If this occurred, then there was a chance that the threads could end in a deadlock, as the Logger object would call back into the MQ classes, which could end up waiting for class initialisation to complete for another thread - which in turn was blocked in the common "java.util.logging.Logger" attempting to write some data to the common trace file. In the case of an IBM MQ classes for JMS application, when this happened, the thread which obtained the "java.util.logging.Logger" lock to be able to write the to trace file would have a stack of the form:; com/ibm/msg/client/commonservices/trace/TableBuilder.<clinit> com/ibm/msg/client/commonservices/j2se/trace/HumanFormatter.writ eHeaderInfo com/ibm/msg/client/commonservices/j2se/trace/HumanFormatter.form at java/util/logging/StreamHandler.publish (entered lock: java/util/logging/FileHandler@0x00000000FFDF1650, entry count: 2) java/util/logging/FileHandler.publish (entered lock: java/util/logging/FileHandler@0x00000000FFDF1650, entry count: 1) java/util/logging/Logger.log java/util/logging/Logger.doLog java/util/logging/Logger.logp com/ibm/msg/client/commonservices/j2se/trace/DefaultTracer.trace Data com/ibm/msg/client/commonservices/trace/Trace.traceDataInternal com/ibm/msg/client/commonservices/trace/Trace.data com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger._traceData com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger.getInstance (entered lock: com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger@0x00000000E00EECD8, entry count: 1) com/ibm/msg/client/commonservices/trace/Trace.getVersion com/ibm/msg/client/commonservices/trace/Trace.setOn (entered lock: com/ibm/msg/client/commonservices/trace/Trace@0x00000000E00EB1E0 , entry count: 1) com/ibm/msg/client/commonservices/trace/Trace.initialize com/ibm/msg/client/commonservices/CommonServices.<clinit> com/ibm/msg/client/commonservices/propertystore/PropertyStore.in itialize com/ibm/msg/client/commonservices/propertystore/PropertyStore.<c linit> com/ibm/msg/client/commonservices/trace/Trace.<clinit> com/ibm/msg/client/jms/internal/JmsReadablePropertyContextImpl.< clinit> MqApplication.myMethod One or more thread stacks of the following form would them also be observed: java/util/logging/FileHandler.publish (entered lock: java/util/logging/FileHandler@0x00000000FFDF1650, entry count: 1) java/util/logging/Logger.log java/util/logging/Logger.doLog java/util/logging/Logger.logp com/ibm/msg/client/commonservices/j2se/trace/DefaultTracer.trace Data com/ibm/msg/client/commonservices/trace/Trace.traceDataInternal com/ibm/msg/client/commonservices/trace/Trace.data com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger._traceData com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger.getInstance (entered lock: com/ibm/msg/client/commonservices/componentmanager/ComponentMana ger@0x00000000E00EF4B0, entry count: 1) com/ibm/msg/client/commonservices/trace/Trace.getVersion com/ibm/msg/client/commonservices/trace/Trace.setOn (entered lock: com/ibm/msg/client/commonservices/trace/Trace@0x00000000E00EAF60 , entry count: 1) com/ibm/msg/client/commonservices/trace/Trace.initialize com/ibm/msg/client/commonservices/CommonServices.<clinit> com/ibm/msg/client/commonservices/propertystore/PropertyStore.in itialize com/ibm/msg/client/commonservices/propertystore/PropertyStore.<c linit> com/ibm/msg/client/commonservices/trace/Trace.<clinit> com/ibm/msg/client/jms/internal/JmsReadablePropertyContextImpl.< clinit> MqApplication.myMethod It should be noted that this deadlock only occurred when: (1) Two or more threads first initialise the IBM MQ classes for Java simultaneously (2) IBM MQ classes for Java trace is enabled (3) Each thread is running on a separate ClassLoader instance
Problem conclusion
The IBM MQ classes for Java, classes for JMS and MQ resource adapter have been updated such that when threads are running using separate Java ClassLoaders, each thread will utilise its own "java.util.logging.Logger" object instance, instead of sharing one between the threads. As a result of this, by default each thread will generate trace to their own ClassLoader specific trace file. For example, if 5 threads are running in the JVM, each under their own ClassLoader, and trace is enabled, after a sufficient amount of trace has been generated to generate 3 wrapping trace files per thread, we would expect to see the following set of trace files: mqjava_14118.cl0.trc.0 mqjava_14118.cl0.trc.1 mqjava_14118.cl0.trc.2 mqjava_14118.cl1.trc.0 mqjava_14118.cl1.trc.1 mqjava_14118.cl1.trc.2 mqjava_14118.cl2.trc.0 mqjava_14118.cl2.trc.1 mqjava_14118.cl2.trc.2 mqjava_14118.cl3.trc.0 mqjava_14118.cl3.trc.1 mqjava_14118.cl3.trc.2 mqjava_14118.cl4.trc.0 mqjava_14118.cl4.trc.1 mqjava_14118.cl4.trc.2 where "14118" corresponds to the ProcessID (PID) of the JVM, and the "cl<num>" corresponds to which ClassLoader the trace was generated under. The default trace name for the MQ classes for Java/JMS has been updated to be of the form: mqjava_%PID%.cl%u.trc and for users of the "com.ibm.mq.mqallclient.jar", the default name has been updated to be of the form: mqjavaclient_%PID%.cl%u.trc The "java.util.logging.Logger" classes substitutes the "%u" in this String with a unique number to avoid filename clashes with other threads. --------------------------------------------------------------- The fix is targeted for delivery in the following PTFs: Version Maintenance Level v8.0 8.0.0.15 v9.0 LTS 9.0.0.10 v9.1 CD 9.1.5 v9.1 LTS 9.1.0.5 The latest available maintenance can be obtained from 'WebSphere MQ Recommended Fixes' http://www-1.ibm.com/support/docview.wss?rs=171&uid=swg27006037 If the maintenance level is not yet available information on its planned availability can be found in 'WebSphere MQ Planned Maintenance Release Dates' http://www-1.ibm.com/support/docview.wss?rs=171&uid=swg27006309 ---------------------------------------------------------------
Temporary fix
Comments
APAR Information
APAR number
IT30255
Reported component name
IBM MQ BASE MP
Reported component ID
5724H7251
Reported release
800
Status
CLOSED PER
PE
NoPE
HIPER
NoHIPER
Special Attention
NoSpecatt / Xsystem
Submitted date
2019-09-11
Closed date
2020-01-27
Last modified date
2020-01-28
APAR is sysrouted FROM one or more of the following:
APAR is sysrouted TO one or more of the following:
Fix information
Fixed component name
IBM MQ BASE MP
Fixed component ID
5724H7251
Applicable component levels
[{"Business Unit":{"code":"BU053","label":"Cloud & Data Platform"},"Product":{"code":"SSYHRD","label":"IBM MQ"},"Component":"","ARM Category":[],"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"8.0.0.0","Edition":"","Line of Business":{"code":"LOB45","label":"Automation"}}]
Document Information
Modified date:
28 January 2020