JDK-4843222 : HotSpot sometimes does not compile methods
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 1.4.1
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: solaris_9
  • CPU: sparc
  • Submitted: 2003-04-04
  • Updated: 2003-04-05
  • Resolved: 2003-04-05
Related Reports
Duplicate :  
Description

Name: jl125535			Date: 04/04/2003


FULL PRODUCT VERSION :
java version "1.4.1_01"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_01-b01)
Java HotSpot(TM) Client VM (build 1.4.1_01-b01, mixed mode)


FULL OPERATING SYSTEM VERSION :

SunOS nexus 5.9 Generic_112233-02 sun4u sparc SUNW,Sun-Fire-880

A DESCRIPTION OF THE PROBLEM :
It is difficult to report this bug in a replicable way, at
least without providing a lot of code and data.

I am including at the profiling results of a run of an HTML
parser on a series of pages, in which the method responsible
for most of the activity (parse()) has not been compiled.
The resulting performance is completely unacceptable, as you
can easily imagine.

On other, seemingly identical runs (same command and arguments),
the VM compiles the method, leading to a 10x speed improvement.

There is no short code that we can provide that replicates
the problem. It is clear that HotSpot is somehow "fooled" by
the complexity of the code, and takes the (completely wrong)
decision not to compile the method that's responsible for
most of the computing time. This happen most of the times
(I'd say 3/4), but not always.

We can either provide you with enough classes and data to
reproduce the bug, or run tests for you trying to understand
what's happening.

Since the problem is not localised in a instruction or in a
method, but is inherently linked to the fact that the code
is complex, it must be debugged from the inside of the JVM.


ERROR MESSAGES/STACK TRACES THAT OCCUR :
Flat profile of 0.01 secs (1 total ticks): SIGTERM handler

  Thread-local ticks:
100.0%     1             Blocked (of total)


Flat profile of 17338.35 secs (733235 total ticks): main

  Interpreted + native   Method
 73.1% 533594  +  1503   ubi.util.PageParser2.parse
  0.6%    12  +  4352    java.util.zip.Inflater.inflateBytes
  0.0%   164  +   198    it.unimi.dsi.fastUtil.Object2ObjectOpenHashMap.<init>
  0.0%     0  +   231    java.io.FileInputStream.readBytes
  0.0%    23  +   128    java.lang.System.arraycopy
  0.0%     3  +   109    java.io.FileOutputStream.writeBytes
  0.0%    56  +    33    java.lang.StringBuffer.expandCapacity
  0.0%    75  +     0    java.util.zip.Inflater.inflate
  0.0%    75  +     0    java.util.zip.Inflater.setInput
  0.0%    63  +     0    sun.nio.cs.UTF_8$Decoder.decodeArrayLoop
  0.0%     0  +    55    it.unimi.dsi.fastUtil.Long2IntOpenHashMap.<init>
  0.0%     3  +    43    ubi.util.Page.read
  0.0%    13  +    29    java.util.zip.Inflater.reset
  0.0%    39  +     0    sun.nio.cs.StreamEncoder$CharsetSE.writeBytes
  0.0%    39  +     0    it.unimi.dsi.mg4j.io.FastBufferedInputStream.read
  0.0%     0  +    35    java.io.BufferedWriter.<init>
  0.0%    30  +     0    java.nio.Buffer.position
  0.0%    27  +     0    ubi.util.OutputAnchorParserCallback.ensureEnd
  0.0%    27  +     0    it.unimi.dsi.fastUtil.Object2ObjectOpenHashMap.<init>
  0.0%     0  +    26    java.io.BufferedOutputStream.<init>
  0.0%    23  +     0    ubi.util.TitleParserCallback.reset
  0.0%    21  +     0    it.unimi.dsi.mg4j.util.MutableString.append
  0.0%    19  +     0    it.unimi.dsi.mg4j.util.MutableString.length
  0.0%    18  +     0    ubi.util.Tokenizer.flush
  0.0%    18  +     0    ubi.util.PrintTitleParserCallback.flush
 74.0% 534859  +  6800   Total interpreted (including elided)

     Compiled + native   Method
  5.8% 42445  +     0    adapters
  2.2% 15835  +     0    sun.nio.cs.UTF_8$Decoder.decodeArrayLoop
  1.3%  9536  +     0    it.unimi.dsi.mg4j.util.MutableString.append
  1.2%  5745  +  3358    ubi.util.Page.read
  1.1%  7844  +     0    ubi.util.PrintOccurrencesParserCallback.handleWord
  1.0%  7205  +     0    it.unimi.dsi.fastUtil.Object2ObjectOpenHashMap.findKey
  1.0%  7091  +     0    java.lang.Character.isLetterOrDigit
  0.8%  6183  +     1    ubi.util.Tokenizer.enqueue
  0.8%  5739  +     1    ubi.util.PageParser2.fixEntities
  0.7%  4943  +    48    ubi.util.Base64.decode
  0.7%  4843  +     0    java.io.BufferedWriter.write
  0.6%  4445  +     0    java.lang.Character.isLetter
  0.6%  4299  +     0    it.unimi.dsi.fastUtil.Object2ObjectOpenHashMap.clear
  0.5%  3780  +     0    ubi.util.Fast.toLowerCase
  0.4%  3247  +     0    ubi.util.Tokenizer.flush
  0.4%  2963  +     0    it.unimi.dsi.mg4j.util.MutableString.hashCode
  0.4%  2711  +     0    sun.nio.cs.UTF_8$Encoder.encodeArrayLoop
  0.4%  2663  +     0    it.unimi.dsi.mg4j.util.MutableString.length
  0.3%  2516  +     0    ubi.util.Base64.decode4to3
  0.3%  2273  +    25    it.unimi.dsi.mg4j.util.MutableString.toString
  0.3%  2137  +     0    ubi.util.URL2.<init>
  0.2%  1654  +    16    java.nio.charset.CharsetEncoder.isLegalReplacement
  0.2%  1488  +     0    vtable chunks
  0.2%  1453  +     0
it.unimi.dsi.fastUtil.Object2ObjectOpenHashMap.findInsertionPoint
  0.2%  1418  +     0    it.unimi.dsi.mg4j.util.MutableString.length
 24.6% 176414  +  3465   Total compiled (including elided)

         Stub + native   Method
  0.6%     9  +  4548    java.util.zip.Inflater.inflateBytes
  0.6%     9  +  4548    Total stub

  Runtime stub + native  Method
  0.0%     6  +     0    _new_typeArray_Java
  0.0%     1  +     0    _new_Java
  0.0%     7  +     0    Total runtime stubs

  Thread-local ticks:
  0.2%  1718             Blocked (of total)
  0.0%     4             Class loader
  0.0%    27             Interpreter
  0.0%     3             Compilation
  0.7%  5279             Unknown: running frame
  0.0%    24             Unknown: calling frame
  0.0%    78             Unknown: thread_state


Global summary of 17338.35 seconds:
100.0% 856557            Received ticks
 13.8% 118070            Received GC ticks
  0.1%  1284             Compilation
  0.0%     2             Other VM operations
  0.0%     4             Class loader
  0.0%    27             Interpreter
  0.6%  5381             Unknown code


REPRODUCIBILITY :
This bug can be reproduced often.

CUSTOMER WORKAROUND :
There is no possible workaround. The problem is deeply
inside the JVM.
(Review ID: 181803) 
======================================================================

Comments
PUBLIC COMMENTS duplicate
10-06-2004

EVALUATION Feedback from original submitter revealed this to be a duplicate of another bug. > No, it is not new, it is bug 4755752. I discussed this issue with Sun Italy, as we have a V880. The bug is fixed in 1.4.1_02 (at least for what we can test). > > Ciao ###@###.### 2003-04-04
04-04-2003