IBM Support

IT30255: IBM MQ classes for Java/JMS hang when trace is enabled for multiple threads running on different classloaders

Subscribe to this APAR

By subscribing, you receive periodic emails alerting you to the status of the APAR, along with a link to the fix after it becomes available. You can track this item individually or track all items by product.

Notify me when this APAR changes.

Notify me when an APAR for this component changes.

 

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":"LOB36","label":"IBM Automation"}}]

Document Information

Modified date:
28 January 2020