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

[coleen.phillimore at oracle.com]

On 2/12/19 3:10 PM, Thomas Stüfe wrote:
>
>
> On Tue, Feb 12, 2019 at 8:54 PM <coleen.phillimore at oracle.com 
> <mailto:coleen.phillimore at oracle.com>> wrote:
>
>
>
>     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.
>
>
> Thank you, appreciated. It does not have a high priority right now, 
> but we may come around to do this.
>
>>
>>         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.
>

I misspoke.   We have class loading events in the generic event section:

Events (10 events):
...
Event: 472.776 Executing VM operation: ZMarkEnd
Event: 472.777 Executing VM operation: ZMarkEnd done
Event: 472.814 loading class org/apache/cassandra/config/CFMetaData
Event: 472.814 loading class org/apache/cassandra/config/CFMetaData done

Coleen

>
>     Coleen
>
>
> ..Thomas
>
>>
>>     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
>>>
>>
>