II12765: LATCH CONTENTION AND HIGH CPU UTILIZATION RUNNING JAVA APPLICATION.

APAR status

• INTRAN

Error description

• This informational apar is being taken to document
  workarounds for latch contention problems for HFS files
  and excessive CPU utilization in latch processing in USS
  that can occur when using common java coding techniques
  in a heavily multi-threaded WebSphere environment.
  
  These problems would occur in java application code
  running on any platform, however, we are describing
  the symptoms for diagnosing the problem on OS/390
  and z/OS operating systems.
  
  Problem (1)
  Typically java.util.Properties.load() and store() are used
  to read and write properties from a text stream, and are a
  convenient way to implement an application configuration
  file.
  
  However, both methods are synchronized. This means that when
  the file is opened by the JVM, it is opened exclusively,
  which means that USS obtains an exclusive latch for the
  file in the file latchset.
    In a heavily multi-threaded WAS environment, this can
  cause contention between threads for this latch.
  From a D GRS,C command the contention might look like this
  PARTIAL LATCH INFORMATION AVAILABLE
  LATCH SET NAME:  SYS.BPX.A000.FSLIT.FILESYS.LSN.01
  CREATOR JOBNAME: OMVS      CREATOR ASID: 000E
    LATCH NUMBER:  686
  591 00000080      REQUESTOR  ASID  EXC/SHR    OWN/WAIT
  591 00000080      WEBSRV     00F8  EXCLUSIVE  OWN
  591 00000080      WEBSRV     00F8  EXCLUSIVE  WAIT
  The traceback for the thread which owned the latch
  looked like this;
  
  Traceback:
  PU Addr   PU Offset  Entry         E Addr    E  Offset   Stateme
  0B4EF508  -0B4EF50A  read          0B4EF508  -0B4EF50A
  1D386C60  +000001E6  sysThreadBlockingSection
                                     1D386C60  +000001E6
  1D391130  +000000F4  sysReadFD     1D391130  +000000F4
  1D2D1F00  +000000C0  java_io_FileInputStream_read
                                     1D2D1F00  +000000C0
  1D29CDD0  +00000074  Java_java_io_FileInputStream_read_stub
                                     1D29CDD0  +00000074
  2EA500F4  +00000070  java/io/FileInputStream.read
                                     2EA500F4  +00000070
  2EA79614  +000000A0  sun/io/LocalizedInputStream.read
                                     2EA79614  +000000A0
  2EB1B020  +00000218  java/util/Properties.load
                                     2EB1B020  +00000218
  2F8B8CD4  +000001BA  user application code
                                     2F8B8CD4  +000001BA
  Note the Properties.load invoked from the
  user application constructor.  The latch contention
  showed in the system trace as the following entries where
  we see the TCB being Suspended to wait for the CEDQ lock to
  be available.
  
  008CBA60   PC    ...   8      810A3949  0130B
  008CBA60   PC    ...   0      81625AAE  0010E
  808CBA60   SUSP               98D4E46C  008CE130 CEDQ
  008C1E88   PC    ...   8      810A3949  0130B
  008C1E88   PC    ...   0      81625AAE  0010E
  808C1E88   SUSP               98D4E46C  008C20A8 CEDQ
  008BD618   PC    ...   8      810A3949  0130B
  008BD618   PC    ...   0      81625AAE  0010E
  808BD618   SUSP               98D4E46C  008BDE00 CEDQ
  
  To bypass this problem use another way of reading and
  writing your application configuration files.
  
  
  Problem (2)
  
  Once the latch contention problem was resolved by not
  using the load(), it was noticed CPU utilization spiked to
  as high as 40% using an OEM performance monitor, it also
  showed the time was being spent in module ISGLOBTF - GRS
  latch obtain code .  The system trace showed the following
  repeated read entries;
  
  008C6098   PC    ...   8      810A3949  0130B
  008C6098   PR    ...   0      810A3949  98E31E6A
  008C6098   PC    ...   8      810A3949  0130B
  008C6098   PR    ...   0      810A3949  98E31E6A
  008C6098   PC    ...   8      810A3949  0130B
  008C6098   PR    ...   0      810A3949  98E31E6A
  
  The PC 130B is a SS-PC into OEMVS for a read syscall.
  The traceback from a slip dump captured on entry to the PC 130B
  showed the Properties.load was no longer used, however, there
  was still high CPU utilization.
  
  Traceback:
  PU Addr   PU Offset  Entry         E Addr    E  Offset   Stateme
  1170FED8  -1083E27A  read          1170FED8  -1083E27A
  2C071C60  +000001E6  sysThreadBlockingSection
                                     2C071C60  +000001E6
  2C07C130  +000000F4  sysReadFD     2C07C130  +000000F4
  2BFBCF00  +000000C0  java_io_FileInputStream_read
                                     2BFBCF00  +000000C0
  2BF87DD0  +00000074  Java_java_io_FileInputStream_read_stub
                                     2BF87DD0  +00000074
  3D78C114  +00000070  java/io/FileInputStream.read
                                     3D78C114  +00000070
  3DEAD3B4  +0000011A  java/io/ObjectInputStream.read
                                     3DEAD3B4  +0000011A
  3E145D84  +00000080  java/io/DataInputStream.readShort
                                     3E145D84  +00000080
  3E14393C  +0000007A  java/io/ObjectInputStream.readShort
                                     3E14393C  +0000007A
  2C07D6C8  +00001248  EXECJAVA      2C07D6C8  +00001248
  2C07D6C8  +00001248  EXECJAVA      2C07D6C8  +00001248
  2C07D6C8  +00001248  EXECJAVA      2C07D6C8  +00001248
  3DDA81B4  +0000087C  User application code
                                     3DDA81B4  +0000087C
  
  The thread had been captured reading a file in the hfs which
  was recognized as the filename of an application data object
  serialized to disk.
    The final determination was the excessive CPU is being
  caused by many reads to the file as the object is
  deserialized before being instantiated.  This is because
  the classes sent use FileInputStream rather than
  BufferedInputStream.  This would mean the file is read
  each time for individual fields within the object, rather
  then read once and buffered.
  
  An example change would be:
  ObjectInputStream inObj = new ObjectInputStream(new
  BufferedInputStream(new FileInputStream
  (FileName.strSeriali etc.
  After making these change large reductions in EXCP count and
  CPU utilization were observed.
  Please IP on this info APAR if you use this information.
  

Local fix

• Problem 1, exclusive latch;
  
  To bypass this problem use another way of reading and writing
  your application configuration files.
  
    Problem 2, High CPU;
  
  An example application code change;
  ObjectInputStream inObj = new ObjectInputStream(new
  BufferedInputStream(new FileInputStream
  (FileName.strSeriali etc.
  

Problem summary

Problem conclusion

Temporary fix

Comments

APAR Information

• APAR is sysrouted FROM one or more of the following:

• APAR is sysrouted TO one or more of the following:

Fix information

Applicable component levels