JDK-8212988 : add recent class unloading events to the hs_err log
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 12
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-10-25
  • Updated: 2019-08-15
  • Resolved: 2019-02-13
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 13
13 b08Fixed
Related Reports
Relates :  
JDK-8153413 - Exceptions::_throw always logs exceptions, penalizing performance
Description
It could be helpful for debugging to include recent class unloading events in the hs_err
Comments
Good suggestion! We might be able to use this mechanism for logging exceptions too. Classes unloaded (10 events): Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800256840 'javasoft/sqe/tests/lang/expr112/expr11201/expr11201' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800256040 'javasoft/sqe/tests/lang/expr113/expr11301/expr11301' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800255040 'javasoft/sqe/tests/lang/expr103/expr10303/expr10303' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800254a50 'javasoft/sqe/tests/lang/expr104/expr10401/Calc' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800254840 'javasoft/sqe/tests/lang/expr104/expr10401/expr10401' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800254040 javasoft/sqe/tests/lang/expr106/expr10601/expr10601' Event: 3.629 Thread 0x00007fb41c25d800 Unloading class 0x0000000800255840 'javasoft/sqe/tests/lang/expr107/expr10701/Triple' Running until I get stable numbers that I like, this seems like it works. $ bash get_avgs 143415 143756 Opening reference.numbers average is 6.460699999999999 Opening less.logging.numbers average is 6.218880000000001
11-02-2019
Maybe the number of messages might be the real problem. Most of the other events are somewhat coarse grained and are associated singly with expensive events, so the performance of the underlying log wasn't a major factor. Class unloading might produce a lot of events at once even though we only end up recording the last 10. I'd be curious if you greatly simplify the message but still keep the message per class if you still measure a performance difference. Maybe the locking overhead is significant? You could make a custom EventLog subclass that directly writes into the buffer instead of creating an intermediate resource string for the class name. I do think including the individual classes provides some extra clues that can be useful but the whole thing is surprisingly expensive.
11-02-2019
Yes, InstanceKlass::external_name() is very expensive because it changes '/' to '.' which we don't care about. If I changed to ik->name()->as_C_string() it's better but it's still slightly slower for the whole "Class Unloading" phase. + java avg less.logging.numbers Opening less.logging.numbers average is 6.952999999999999 + java avg reference.unloading Opening reference.unloading average is 6.9037 Reporting just the class loader, with the address of the ClassLoaderData, might be just as helpful and doesn't cause any performance difference at all. Classes unloaded (10 events): Event: 0.635 Thread 0x00007ff52425d800 unloading class loader runThese$DirectoryClassLoader @124f97bc 0x00007ff47c033100 Event: 0.635 Thread 0x00007ff52425d800 unloading class loader runThese$DirectoryClassLoader @536d734f 0x00007ff49002d4b0 Event: 0.635 Thread 0x00007ff52425d800 unloading class loader runThese$DirectoryClassLoader @75ff9e63 0x00007ff47403b8c0 ...
11-02-2019
Seems like a lot of cost for producing log messages. Maybe something is really inefficient about the string message production? The other downside of the EventLog is that it causes some serialization but I assume class unloading is serial anyway. I'd added this locally when tracking JVMCI GC problems and wasn't sure of the source. The class unloading messages made it clearer where the bug was. It provides a nice clue that some unloading has occurred. Maybe it doesn't require the per class unloading messages? Maybe the class loader level detail is sufficient if the per class is too expensive.
08-02-2019
I was thinking these are such tiny numbers they probably don't matter but averaging total class unloading time for dacapo from these lines: iteration.1/DaCapo2009/data/gc.log:[23.792s][debug][gc,phases] GC(12) Class Unloading 1.249ms $ !java java avg reference.unloading Opening reference.unloading average is 6.9037 $ java avg logging.unloading Opening logging.unloading average is 7.070959999999998 One extra ms average? Still a tiny number idk. [~stefank] ?
08-02-2019
I was doing some performance testing on this change with daCapo and the average ClassLoaderDataGraph times are higher with this logging. I took out logging the class loader name to see if that would help. From 5 iterations of daCapo: iteration.1/DaCapo2009/data/gc.log:[0.347s][debug][gc,phases] GC(0) ClassLoaderData 0.002ms ... And running a small average script on the times: $ java avg reference Opening reference average is 0.39697999999999994 $ java avg logging.new Opening logging.new average is 0.50326 The Events logging is on by default. I'm not really happy about this. We thought this would be useful for another bug that we're looking at.
08-02-2019
We have a version of this in our JDK 8 sources that looks pretty much like yours though I left out the loader because I didn't really think of it. I'm happy if you are interested in taking it. I'd intended to bring it forward but I'll probably adopt your version in jvmci 8 just for consistency. Class unloading (10 events): Event: 6.930 Thread 0x00007fb64f078800 unloaded java.lang.invoke.LambdaForm$MH/1272457345 0x00000007c027e830 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$57/805189653 0x00000007c027e430 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$51/1970881185 0x00000007c027d830 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$56/1681832320 0x00000007c027e030 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$55/1774372677 0x00000007c027d030 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$54/1338562892 0x00000007c027cc30 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$53/1683266754 0x00000007c027dc30 Event: 6.930 Thread 0x00007fb64f078800 unloaded com.oracle.svm.hosted.ImageClassLoader$1$$Lambda$52/1159716434 0x00000007c027c830 Event: 18.511 Thread 0x00007fb64f078800 unloaded sun.reflect.GeneratedConstructorAccessor44 0x00000007c04bf030 Event: 18.511 Thread 0x00007fb64f078800 unloaded sun.reflect.GeneratedConstructorAccessor33 0x00000007c03d4430
08-02-2019
Classes unloaded (10 events): Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss019.clss01901.clss01901 0x0000000800101040 in loader runThese$DirectoryClassLoader @5e14e5f1 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss020.clss02001.clss02001_b 0x0000000800109840 in loader runThese$DirectoryClassLoader @28247928 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss020.clss02001.clss02001_a 0x0000000800100c68 in loader runThese$DirectoryClassLoader @28247928 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss020.clss02001.clss02001_i 0x0000000800100a58 in loader runThese$DirectoryClassLoader @28247928 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss020.clss02001.clss02001 0x0000000800100840 in loader runThese$DirectoryClassLoader @28247928 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss015.clss01501.clss01501 0x00000008000ff040 in loader runThese$DirectoryClassLoader @6f07bc49 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss012.clss01215.aaa.bbb.ccc.clss01215_a 0x00000008000fea58 in loader runThese$DirectoryClassLoader @52442859 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss012.clss01215.aaa.bbb.ccc.clss01215 0x00000008000fe840 in loader runThese$DirectoryClassLoader @52442859 Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss012.clss01214.aaa.bbb.ccc.clss01214_a 0x00000008000fda58 in loader runThese$DirectoryClassLoader @60a48bff Event: 1.342 Thread 0x00007f7084392800 unloading class javasoft.sqe.tests.lang.clss012.clss01214.aaa.bbb.ccc.clss01214 0x00000008000fd840 in loader runThese$DirectoryClassLoader @60a48bff
07-02-2019
[~never] I'm going to take this (unless you already have the patch). Thanks.
05-02-2019