David/Peter you are right, the logs trace came from passed run, i am trying to simulate the failure and get the logs for failed runs(2000+ runs done and still no failure), will get back to you once i have the data from failed run. Sorry for the confusion.

---
Thanks
kalyan

On 01/08/2014 11:22 PM, David Holmes wrote:
Thanks Peter.

Kalyan: Can you confirm, as Peter asked, that the TraceExceptions output came from a failed run?

AFAICS the Trace info is printed after each bytecode where there is a pending exception - though I'm not 100% sure on the printing within the VM runtime. Based on that I think we see the Trace output in run() at the point where wait() returns, so it may well be caught after that - in which case this was not a failing run.

I also can't reproduce the problem :(

David

On 8/01/2014 10:34 PM, Peter Levart wrote:
On 01/08/2014 07:30 AM, David Holmes wrote:
On 8/01/2014 4:19 PM, David Holmes wrote:
On 8/01/2014 7:33 AM, srikalyan chandrashekar wrote:
Hi David, TraceExceptions with fastdebug build produced some nice trace <http://cr.openjdk.java.net/%7Esrikchan/OOME_exception_trace.log> . The native method wait(long) is where the OOME if being thrown, the deepest
call is in

src/share/vm/gc_interface/collectedHeap.inline.hpp, line 157

Yes but it is the caller that is of interest:

Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
thrown
[/HUDSON/workspace/8-2-build-linux-amd64/jdk8/1317/hotspot/src/share/vm/runtime/objectMonitor.cpp,

line 1649]
for thread 0x00007f78c40d2800
Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
  thrown in interpreter method <{method} {0x00007f78b4800ae0} 'wait'
'(J)V' in 'java/lang/Object'>
  at bci 0 for thread 0x00007f78c40d2800

The ReferenceHandler thread gets the OOME trying to allocate the
InterruptedException.

However we already have a catch block around the wait() so how is this
OOME getting through? A bug in exception handling in the interpreter ??


Might be. And it may have something to do with the fact that the
Thread.run() method is the 1st call frame on the thread's stack (seems
like corner case). The last few meaningful TraceExceptions records are:


Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
thrown
[/HUDSON/workspace/8-2-build-linux-amd64/jdk8/1317/hotspot/src/share/vm/gc_interface/collectedHeap.inline.hpp,
line 157]
for thread 0x00007f78c40d2800
Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
thrown
[/HUDSON/workspace/8-2-build-linux-amd64/jdk8/1317/hotspot/src/share/vm/runtime/objectMonitor.cpp,
line 1649]
for thread 0x00007f78c40d2800
Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
  thrown in interpreter method <{method} {0x00007f78b4800ae0} 'wait'
'(J)V' in 'java/lang/Object'>
  at bci 0 for thread 0x00007f78c40d2800
Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
  thrown in interpreter method <{method} {0x00007f78b4800ca8} 'wait'
'()V' in 'java/lang/Object'>
  at *bci 2* for thread 0x00007f78c40d2800
Exception <a 'java/lang/OutOfMemoryError'> (0x00000000d6a01840)
  thrown in interpreter method <{method} {0x00007f78b48d2250} 'run'
'()V' in 'java/lang/ref/Reference$ReferenceHandler'>
  at *bci 36* for thread 0x00007f78c40d2800


Here's the relevant bytecodes:


public class java.lang.Object

   public final void wait() throws java.lang.InterruptedException;
     descriptor: ()V
     flags: ACC_PUBLIC, ACC_FINAL
     Code:
       stack=3, locals=1, args_size=1
          0: aload_0
          1: lconst_0
*         2: invokevirtual #73                 // Method wait:(J)V*
          5: return
       LineNumberTable:
         line 502: 0
         line 503: 5
     Exceptions:
       throws java.lang.InterruptedException


class java.lang.ref.Reference$ReferenceHandler extends java.lang.Thread

   public void run();
     descriptor: ()V
     flags: ACC_PUBLIC
     Code:
       stack=2, locals=5, args_size=1
          0: invokestatic  #62                 // Method
java/lang/ref/Reference.access$100:()Ljava/lang/ref/Reference$Lock;
          3: dup
          4: astore_2
          5: monitorenter
          6: invokestatic  #61                 // Method
java/lang/ref/Reference.access$200:()Ljava/lang/ref/Reference;
          9: ifnull        33
         12: invokestatic  #61                 // Method
java/lang/ref/Reference.access$200:()Ljava/lang/ref/Reference;
         15: astore_1
         16: aload_1
         17: invokestatic  #64                 // Method
java/lang/ref/Reference.access$300:(Ljava/lang/ref/Reference;)Ljava/lang/ref/Reference;
         20: invokestatic  #63                 // Method
java/lang/ref/Reference.access$202:(Ljava/lang/ref/Reference;)Ljava/lang/ref/Reference;
         23: pop
         24: aload_1
         25: aconst_null
         26: invokestatic  #65                 // Method
java/lang/ref/Reference.access$302:(Ljava/lang/ref/Reference;Ljava/lang/ref/Reference;)Ljava/lang/ref/Reference;
         29: pop
         30: goto          52
         33: invokestatic  #62                 // Method
java/lang/ref/Reference.access$100:()Ljava/lang/ref/Reference$Lock;
*        36: invokevirtual #59                 // Method
java/lang/Object.wait:()V*
         39: goto          43
         42: astore_3
         43: goto          47
         46: astore_3
         47: aload_2
         48: monitorexit
         49: goto          0
         52: aload_2
         53: monitorexit
         54: goto          64
         57: astore        4
         59: aload_2
         60: monitorexit
         61: aload         4
         63: athrow
         64: aload_1
         65: instanceof    #38                 // class sun/misc/Cleaner
         68: ifeq          81
         71: aload_1
         72: checkcast     #38                 // class sun/misc/Cleaner
         75: invokevirtual #67                 // Method
sun/misc/Cleaner.clean:()V
         78: goto          0
         81: aload_1
         82: getfield      #57                 // Field
java/lang/ref/Reference.queue:Ljava/lang/ref/ReferenceQueue;
         85: astore_2
         86: aload_2
         87: getstatic     #58                 // Field
java/lang/ref/ReferenceQueue.NULL:Ljava/lang/ref/ReferenceQueue;
         90: if_acmpeq     99
         93: aload_2
         94: aload_1
         95: invokevirtual #66                 // Method
java/lang/ref/ReferenceQueue.enqueue:(Ljava/lang/ref/Reference;)Z
         98: pop
         99: goto          0
       Exception table:
          from    to  target type
*            33    39    42   Class java/lang/OutOfMemoryError*
             33    43    46   Class java/lang/InterruptedException
              6    49    57   any
             52    54    57   any
             57    61    57   any
       StackMapTable: number_of_entries = 11
            frame_type = 0 /* same */
            frame_type = 253 /* append */
           offset_delta = 32
           locals = [ top, class java/lang/Object ]
              frame_type = 72 /* same_locals_1_stack_item */
             stack = [ class java/lang/OutOfMemoryError ]
              frame_type = 0 /* same */
              frame_type = 66 /* same_locals_1_stack_item */
             stack = [ class java/lang/InterruptedException ]
              frame_type = 0 /* same */
              frame_type = 255 /* full_frame */
             offset_delta = 4
             locals = [ class java/lang/ref/Reference$ReferenceHandler,
class java/lang/ref/Reference, class java/lang/Object ]
             stack = []
              frame_type = 255 /* full_frame */
             offset_delta = 4
             locals = [ class java/lang/ref/Reference$ReferenceHandler,
top, class java/lang/Object ]
             stack = [ class java/lang/Throwable ]
              frame_type = 255 /* full_frame */
             offset_delta = 6
             locals = [ class java/lang/ref/Reference$ReferenceHandler,
class java/lang/ref/Reference ]
             stack = []
              frame_type = 16 /* same */
              frame_type = 250 /* chop */
             offset_delta = 17

         LineNumberTable:
           line 136: 0
           line 137: 6
           line 138: 12
           line 139: 16
           line 140: 24
           line 157: 33
           line 158: 39
           line 159: 43
           line 160: 47
           line 162: 52
           line 165: 64
           line 166: 71
           line 167: 78
           line 170: 81
           line 171: 86
           line 172: 99
   }


... if I understand correctly the TraceExceptions' output, one record is
printed for each abruptly completed method. The last record printed
shows that Object.wait() method completed abruptly by throwing OOME.
Even if the OOME was caught and ignored, we would still get this
TraceExceptions record. Am I right? There's no record of abruptly
terminated ReferenceHandler.run() method in the output. This might be
because there's no method "calling" the ReferenceHandler.run() method,
since it is the 1st method on the call-stack. Are you sure the output is
from a failed test?

Can we make the following adjustment to the ReferenceHandler and see
what gets printed and/or whether we still get uncaught OOME:


     private static class ReferenceHandler extends Thread {
     ...
         public void run() {
             runImpl();
         }

         private void runImpl() {
             // ... the content of the original run() method
         }
     ...




Regards, Peter

David

David
-----

------------------- Excerpt Begins ---------------------

147  if (!gc_overhead_limit_was_exceeded) {
148    // -XX:+HeapDumpOnOutOfMemoryError and -XX:OnOutOfMemoryError
support
149    report_java_out_of_memory("Java heap space");
150
151    if (JvmtiExport::should_post_resource_exhausted()) {
152      JvmtiExport::post_resource_exhausted(
153        JVMTI_RESOURCE_EXHAUSTED_OOM_ERROR |
JVMTI_RESOURCE_EXHAUSTED_JAVA_HEAP,
154        "Java heap space");
155    }
156
157 THROW_OOP_0(Universe::out_of_memory_error_java_heap());
158  } else {

------------------- Excerpt Ends ---------------------


Would be helpful if David/some one else in the team could explain the
latent aspects/probable cause.

---
Thanks
kalyan

On 01/06/2014 04:40 PM, David Holmes wrote:
Back from vacation ...

On 20/12/2013 4:49 PM, David Holmes wrote:
On 20/12/2013 12:57 PM, srikalyan chandrashekar wrote:
Hi David Thanks for your comments, the unguarded part(clean and
enqueue)
in the Reference Handler thread does not seem to create any new
objects,
so it is the application(the test in this case) which is adding
objects
to heap and causing the Reference Handler to die with OOME.

The ReferenceHandler thread can only get OOME if it allocates
(directly
or indirectly) - so there has to be something in the unguarded part
that
causes this. Again it may be an implicit action in the VM -
similar to
the class load issue for InterruptedException.

Run a debug VM with -XX:+TraceExceptions to see where the OOME is
triggered.

David
-----

David

I am still
unsure about the side effects of the code change and agree with your
thoughts(on memory exhaustion test's reliability).

PS: hotspot dev alias removed from CC.

--
Thanks
kalyan

On 12/19/13 5:08 PM, David Holmes wrote:
Hi Kalyan,

This is not a hotspot issue so I'm moving this to core-libs, please
drop hotspot from any replies.

On 20/12/2013 6:26 AM, srikalyan wrote:
Hi all,  I have been working on the bug JDK-8022321
<https://bugs.openjdk.java.net/browse/JDK-8022321> , this is a
sporadic
failure and the webrev is available here
http://cr.openjdk.java.net/~srikchan/Regression/JDK-8022321_OOMEInReferenceHandler-webrev/






I'm really not sure what to make of this. We have a test that
triggers
an out-of-memory condition but the OOME can actually turn up in the
ReferenceHandler thread causing it to terminate and the test to
fail.
We previously accounted for the non-obvious occurrences of OOME
due to
the Object.wait and the possible need to load the
InterruptedException
class - but still the OOME can appear where we don't want it. So
finally you have just placed the whole for(;;) loop in a
try/catch(OOME) that ignores the OOME. I'm certain that makes the
test
happy, but I'm not sure it is really what we want for the
ReferenceHandler thread. If the OOME occurs while cleaning, or
enqueuing then we will fail to clean and/or enqueue but there
would be
no indication that has occurred and I think that is a bigger
problem
than this test failing.

There may be no way to make this test 100% reliable. In fact I'd
suggest that no memory exhaustion test can be 100% reliable.

David

*
**"Root Cause:Still not known"*
2 places where there is a possibility for OOME
1) Cleaner.clean()
2) ReferenceQueue.enqueue()

1) The cleanup code in turn has 2 places where there is potential
for
throwing OOME,
     a) thunk Thread which is run from clean() method. This
Runnable is
passed to Cleaner and appears in the following classes
         java/nio/DirectByteBuffer.java
         sun/misc/Perf.java
         sun/nio/fs/NativeBuffer.java
         sun/nio/ch/IOVecWrapper.java
         sun/misc/Cleaner/ExitOnThrow.java
However none of the above overridden implementations ever
create an
object in the clean() code.
     b) new PrivilegedAction created in try catch Exception
block of
clean() method but for this object to be created and to be held
responsible for OOME an Exception(other than OOME) has to be
thrown.

2) No new heap objects are created in the enqueue method nor
anywhere in
the deep call stack (VM.addFinalRefCount() etc) so this cannot
be a
potential cause.

*Experimental change to java.lang.Reference.java* :
- Put one more guard (try catch with OOME block) in the Reference
Handler Thread which may give the Reference Handler a chance to
cleanup.
This is fixing the test failure (several 1000 runs with 0
failures)
- Without the above change the test fails atleast 3-5 times for
every
1000 run.

*PS*: The code change is to a very critical part of JDK and i am
fully
not aware of the consequences of the change, hence seeking expert
help
here. Appreciate your time and inputs towards this.





Reply via email to