JDK-8166145 : runtime/threads/ThreadInterruptTest3 fails with ExitCode 0
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 9
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2016-09-15
  • Updated: 2017-07-19
  • Resolved: 2016-10-27
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 b146Fixed
Related Reports
Duplicate :  
JDK-8166295 - [TESTBUG] nsk/regression/b4318701 b4324656 b4330134 fail with exit code 97
Relates :  
JDK-8168151 - Why do we need BasicHashtableEntry::next_addr() API?
Relates :  
JDK-8138760 - [JVMCI] VM warning: Performance bug: SystemDictionary lookup_count=21831450 lookup_length=1275207287 average=58.411479 load=5.572844
Relates :  
JDK-8166295 - [TESTBUG] nsk/regression/b4318701 b4324656 b4330134 fail with exit code 97
Relates :  
JDK-8167232 - Convert Dictionary::print() to UL
Relates :  
JDK-8166848 - Performance bug: SystemDictionary - optimization
Description
This failure happened in PIT on Linux-x86
Comments
After some more thinking I think Christian (and David) was right - printing debug info about SystemTable is interfering with tests, such as this one that use golden file for comparing expected output. We will loose coverage if we convert the debug info to UL, but as it is, we only hear about this performance issue, when it interferes with a test. We should convert this debug info to UL and only enable it for performance testing, or create a specific test for such purpose. I'm going to use this one then to track converting the debug info to UL, and that means that we can close JDK-8166295 as a duplicate of this one, just as Christian originally did. We will need another issue to track fixing the performance of SystemDictionary.
23-09-2016
JDK-8166295 is tracking the regression and has the failing tests. I'm leaving this issue to deal exclusively with the performance.
20-09-2016
Christian, can you point to the broken tests? Will converting the output to UL actually fix that?
19-09-2016
This output should be changed to use the UL framework, this has started to break a bunch of tests in our nightly/PIT and has to be addressed for JdK9.
19-09-2016
The most heavily looked up bucket (ie. at index 994) takes up slightly more than 1/3rd of the total lookup count: [2016-09-11T02:17:58.09] 994: 0: 34.53%: 4288661657: jdk.internal.loader.BootLoader, loader NULL class_loader [2016-09-11T02:17:58.09] 994: 1: 34.53%: 4287189526: java.lang.Class$AnnotationData, loader NULL class_loader [2016-09-11T02:17:58.09] 994: 2: 34.53%: 4116356745: java.lang.LinkageError, loader NULL class_loader [2016-09-11T02:17:58.09] 994: 3: 34.53%: 4083397760: java.lang.Object, loader NULL class_loader The last item in the chain of that bucket is, unsurprisingly, "java.lang.Object", which is most likely the entry that gets looked up the most out of these 4. In this case it would be more efficient if "java.lang.Object" was the first one in the chain. Any adjustment to the size of the table will not help, as eventually, due to the randomness of the hash computing function, will lead to a similar situation eventually (arguably with lesser chance the bigger table is) Can we keep "java.lang.Object" always at the front of the bucket's entries?
15-09-2016
Thank you.
15-09-2016
Gerard - IIRC you were looking for an instance of this warning: Java HotSpot(TM) Server VM warning: Performance bug: SystemDictionary lookup_count=40506 lookup_length=48649 average=1.201032 load=0.573835 with the new diagnostic output.
15-09-2016
This is a "golden" file comparison style test; the test passes if the output matches the golden file (ThreadInterruptTest3.pass) and fails otherwise. In this particular case, the test ran into this warning in stderr: Java HotSpot(TM) Server VM warning: Performance bug: SystemDictionary lookup_count=40506 lookup_length=48649 average=1.201032 load=0.573835 along with a bunch of diagnostic output in stdout: ======< Gold file= /export/home/aurora/sandbox/results/ResultDir/ThreadInterruptTest3/ThreadInterruptTest3.eout.filtered ======> Output file=/export/home/aurora/sandbox/results/ResultDir/ThreadInterruptTest3/ThreadInterruptTest3.pass 1,1174c1 < *+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+Java system dictionary (table_size=1009, classes=579) < ^ indicates that initiating loader is different from defining loader < 1st number: th bucket index < 2nd number: the entry's index within this bucket < 3rd number: the hit percentage of this entry < 4th number: the hash index of this entry < 0: < 1: < 2: < 3: < 4: < 5: 0: 0.14%: 3313508582: java.lang.module.ModuleReference, loader NULL class_loader < 6: < 7: 0: 0.01%: 4035288662: java.lang.Class$5, loader NULL class_loader < 8: 0: 0.07%: 4033435130: java.lang.Character, loader NULL class_loader < 9: 0: 0.01%: 4032887244: java.nio.channels.FileChannel$MapMode, loader NULL class_loader < 10: 0: 0.01%: 3786410743: java.lang.CharacterDataLatin1, loader NULL class_loader <snip> < 998: 0: 0.01%: 3272837794: java.lang.invoke.MutableCallSite, loader NULL class_loader < 999: < 1000: 0: 0.01%: 4114051186: java.lang.StringCoding, loader NULL class_loader < 1001: < 1002: 0: 0.02%: 3245398043: java.lang.reflect.AccessibleObject, loader NULL class_loader < 1003: < 1004: < 1005: 0: 0.01%: 3841988467: sun.nio.ch.Interruptible, loader NULL class_loader < 1006: < 1007: 0: 0.01%: 3537773960: jdk.internal.misc.JavaLangRefAccess, loader NULL class_loader < 1008: < < Top 16 buckets: < 543: hits 4.43% < 493: hits 0.56% < 525: hits 11.51% < 769: hits 5.47% < 176: hits 0.72% < 871: hits 16.16% < 12: hits 0.42% < 536: hits 4.61% < 994: hits 34.53% < 764: hits 0.43% < 134: hits 0.65% < 13: hits 4.11% < 12: hits 0.42% < 13: hits 4.11% < 945: hits 5.51% < 510: hits 0.87% < < Protection domain cache table (table_size=137, classes=2) < entry 0xcb7cf4a0 value 0xd2280778 strongly_reachable 0 next 0x00000000 < entry 0xcb7cf4b4 value 0xd2288358 strongly_reachable 0 next 0x00000000 < --- > *+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+*+
15-09-2016