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

[Thomas Stüfe]

On Tue, Feb 12, 2019 at 8:54 PM <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> 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.
>
> Coleen
>
>
..Thomas


>
> Cheers, Thomas
>
>
>> Coleen
>>
>>
>> Cheers, Thomas
>>
>>
>> On Tue, Feb 12, 2019 at 4:20 PM <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
>>>
>>
>>
>