JDK-8158946 : btree009 fails with assert(s > 0) failed: Bad size calculated
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P2
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2016-06-07
  • Updated: 2018-06-21
  • Resolved: 2016-07-05
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b129Fixed
Related Reports
Relates :  
JDK-8039904 - dtrace/hotspot/Monitors/Monitors001 fails with "assert(s > 0) failed: Bad size calculated"
Relates :  
JDK-8160369 - Memory fences needed around setting and reading object lengths
Description
#  Internal Error (hotspot/src/share/vm/oops/oop.inline.hpp:262), pid=2286, tid=2312
#  assert(s > 0) failed: Bad size calculated
#

---------------  T H R E A D  ---------------

Current thread (0xe34d0400):  ConcurrentGCThread "CMS Main Thread" [stack: 0xe327f000,0xe3300000] [id=2312]

Stack: [0xe327f000,0xe3300000],  sp=0xe32fee90,  free space=511k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x149fb17]  VMError::report_and_die(int, char const*, char const*, char*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned int)+0x137
V  [libjvm.so+0x14a0810]  VMError::report_and_die(Thread*, char const*, int, char const*, char const*, char*)+0x30
V  [libjvm.so+0x92a8e0]  report_vm_error(char const*, int, char const*, char const*, ...)+0x60
V  [libjvm.so+0x712fa0]  oopDesc::size_given_klass(Klass*)+0xd0
V  [libjvm.so+0x8e9cf9]  SweepClosure::do_live_chunk(FreeChunk*)+0x2a9
V  [libjvm.so+0x8eb1b1]  SweepClosure::do_blk_careful(HeapWord*)+0x241
V  [libjvm.so+0x87cbb1]  CompactibleFreeListSpace::blk_iterate_careful(BlkClosureCareful*)+0x31
V  [libjvm.so+0x8f1f97]  CMSCollector::sweepWork(ConcurrentMarkSweepGeneration*)+0x177
V  [libjvm.so+0x8f6d5f]  CMSCollector::sweep()+0x1bf
V  [libjvm.so+0x8f7f91]  CMSCollector::collect_in_background(GCCause::Cause)+0x331
V  [libjvm.so+0x906c1f]  ConcurrentMarkSweepThread::run_service()+0x1df
V  [libjvm.so+0x8d9923]  ConcurrentGCThread::run()+0x73
V  [libjvm.so+0x1171224]  thread_native_entry(Thread*)+0x124
C  [libpthread.so.0+0x6b2c]  start_thread+0xcc


---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
  0xe188e400 JavaThread "nsk.sysdict.share.SysDictTest$Worker@120ebad" [_thread_in_vm, id=2327, stack(0xe4e2e000,0xe4e7f000)]
  0xe30de800 JavaThread "Service Thread" daemon [_thread_blocked, id=2325, stack(0xe502e000,0xe507f000)]
  0xe307ec00 JavaThread "Common-Cleaner" daemon [_thread_blocked, id=2322, stack(0xe542c000,0xe547d000)]
  0xe3023c00 JavaThread "Sweeper thread" daemon [_thread_blocked, id=2321, stack(0xe572e000,0xe577f000)]
  0xe3022000 JavaThread "C1 CompilerThread2" daemon [_thread_blocked, id=2320, stack(0xe207f000,0xe2100000)]
  0xe3020400 JavaThread "C2 CompilerThread1" daemon [_thread_blocked, id=2319, stack(0xe227f000,0xe2300000)]
  0xe301e800 JavaThread "C2 CompilerThread0" daemon [_thread_blocked, id=2318, stack(0xe247f000,0xe2500000)]
  0xe301c800 JavaThread "Signal Dispatcher" daemon [_thread_blocked, id=2317, stack(0xe592e000,0xe597f000)]
  0xe301ac00 JavaThread "Reference Pending List Locker" daemon [_thread_blocked, id=2316, stack(0xe5b2e000,0xe5b7f000)]
  0xe300a400 JavaThread "Finalizer" daemon [_thread_blocked, id=2315, stack(0xe5d2e000,0xe5d7f000)]
  0xe2ffd400 JavaThread "Reference Handler" daemon [_thread_blocked, id=2314, stack(0xe6206000,0xe6257000)]
  0xf5910000 JavaThread "main" [_thread_blocked, id=2290, stack(0xf7752000,0xf77a3000)]
Comments
Bugs found by nightly testing. Verified by passed nightly.
26-07-2017
Thanks Eric. Yes, you are right. I spent the weekend mis-remembering the assertion failure as "size was negative", and since the error listed above results in size = 0, I was certain there was an additional error lurking here some where. But that was a false alarm. The error case above completely explains the failure seen, and is a pre-existing (but very rare) bug. So not an integration blocker.
20-06-2016
Derek: this doesn't seem like a new bug, should the integration_locker tag be removed? btw, great analysis!
20-06-2016
Here's a theory of the crime: CMS is in the middle of a sweep (CMSCollector::sweepWork()). Java thread loads a large class (many static fields), eventually calls InstanceMirrorKlass::allocate_instance(). Java thread: - Does a CMSSynchronousYieldRequest. CMS thread: - Notices the CMSSynchronousYieldRequest. - Releases free list lock. Java thread: - Gets the free list lock. - Allocates java.lang.Class instance in directly in CMSGen (because it's a large object). - Releases the free list lock. CMS thread: - Gets the free list lock. - Resumes scan. - Scans the newly allocated object ASSERTION FAILURE - Because the Java thread has not yet called java_lang_Class::set_oop_size(), which is needed to compute InstanceKlassMirror::oop_size(). Note that CMS doesn't *need* to call oop_size() - it knows the size based on the mark bits. But its uses oop_size() to verify the mark bits in non-production builds. FYI: InstanceMirrorKlass::allocate_instance(KlassHandle k, TRAPS) { int size = instance_size(k); KlassHandle h_k(THREAD, this); instanceOop i = (instanceOop)CollectedHeap::obj_allocate(h_k, size, CHECK_NULL); java_lang_Class::set_oop_size(i, size); return i; }
17-06-2016
I just talked to Derek about this failure and there seem to be too many possibilities about what is going on. I'd suggest getting more information and delay further analysis until we have it. Add some diagnostics at the point where the assertion failure happens and dump out the numbers used in the size calculation is the size used in the assertion is < 0. Turn on classloading logging to see if the failure is for a class recently loaded. That will help to decide if this is a problem with object initialization.
17-06-2016
Poking around core file doesn't show how we get to a negative value (yet)
14-06-2016