RFR (S) 8212988: add recent class unloading events to the hs_err log

[coleen.phillimore at oracle.com]

On 2/12/19 1:41 PM, Thomas Stüfe wrote:
>
>
> On Tue, Feb 12, 2019 at 5:51 PM <coleen.phillimore at oracle.com 
> <mailto:coleen.phillimore at oracle.com>> wrote:
>
>
>
>     On 2/12/19 10:57 AM, Thomas Stüfe wrote:
>>     Hi Coleen,
>>
>>     this is useful.
>
>     We have had some problems where the class is unloaded and this
>     would help with diagnosing this.
>>
>>     Why just InstanceKlass?
>
>     This is all we report when using -Xlog:class+unload, also arrays
>     are only unloaded when their InstanceKlass (bottom_klass) are
>     unloaded so this didn't seem like useful additional information.
>
>>
>>     Why is the pointer interesting in the event log printout?
>
>     When debugging core files after the fact, we might have logging
>     that this class was unloaded and some field off the pointer may be
>     also found in the core file.  It might not be that helpful to have
>     the InstanceKlass pointer vs. some other metaspace pointer
>     though.   Including the pointer was to help with core file
>     analysis though.  Maybe there could be a different pointer printed ?
>>
> I think that makes sense, especially for post mortem analysis. Even 
> more if you combine it with a class load event.
>
>>     Since we pay always for this, how about offloading the format
>>     printf to when the log is actually printed. You could use,
>>     as EventRecord payload, a struct containing the strduped class
>>     name and its IK*. Then you only pay for the strdup, not for the
>>     whole format printf, and not for the multiple copies of the
>>     prefix text.
>
>     I didn't want to deconstruct this further for performance sake. 
>     Most of the changes are to keep the performance neutral since we
>     always pay.  Most of the Events are infrequent and this is
>     relatively infrequent also.  Events for exceptions are less
>     infrequent so that would benefit more from more deconstruction
>     than this would.
>
>
> Okay, fair enough.
>
> Whenever I see the event log code I think we should make this cheaper.
>
> In our proprietary fork we have a generic solution where the format 
> printing is offloaded to printing time. We store the format string and 
> the first three va-arg parameters in the event record, with some 
> special handling for string args which may need duplicating. It works 
> and is cheap but a bit hard wired and maybe not the most pretty solution.
>
> Also, the pressure is not high in the OpenJDK since its event logs are 
> not that "hot". In our fork we log way more frequently, so costs 
> became an issue.

This is interesting.  If you have patches to improve this, I'm open to 
reviewing them if you want to upstream them.  At SAP you seem to do more 
debugging based on information in the hs_err_pid file.

>
>     Thanks for your comments.  What do you think?
>
>
> I think your patch looks fine. One could improve upon it (e.g. log 
> class loading etc) but it is not necessary to make this useful.

Thank you!  We usually don't have bugs related to class loading vs 
unloading, and we already have unified logging that helps debug those 
issues.

Coleen

>
> Cheers, Thomas
>
>     Coleen
>>
>>     Cheers, Thomas
>>
>>
>>     On Tue, Feb 12, 2019 at 4:20 PM <coleen.phillimore at oracle.com
>>     <mailto:coleen.phillimore at oracle.com>> wrote:
>>
>>         Summary: also moved class unloading logging in expected place.
>>
>>         Tested with assert to verify hs_err_file, some dacapo
>>         performance
>>         testing, and hs tier1-6.  See bug for details.
>>
>>         open webrev at
>>         http://cr.openjdk.java.net/~coleenp/2019/8212988.01/webrev
>>         bug link https://bugs.openjdk.java.net/browse/JDK-8212988
>>
>>         Thanks,
>>         Coleen
>>
>