Event descriptions are truncated in logs

[Thomas Stüfe]

I have to agree with Yasumasa though that this problem is annoying and
worth solving.

I can see some alternatives to the existing implementation.

In our propietary port, we changed event writing a lot: we not resolve
the printf messages at log time but we store format string and varargs
separately and do the printf when - if - the even log is printed. If
varargs are pointers to short lived strings, they are copied into some
form of ring buffer. Its okay if maybe a bit overengineered and you
loose type info for the varargs.

A simpler alternative would be to abandon the "fixed 256 bytes per
event record" notion for a more fluent scheme: you still have a global
pre-allocated fixed sized char buffer, but organized as ring buffer
and each record's string can be variable sized. That way short
messages do not use up 256 bytes. So we use the char memory more
efficiently and also can better, in total, tweak the size we want to
give to the event strings.

..Thomas




On Fri, Jun 8, 2018 at 12:29 AM, David Holmes <david.holmes at oracle.com> wrote:
> Hi Yasumasa,
>
> I have to agree with Thomas, full dynamic buffer management is just too
> costly and risky to always use in these cases. Also agree about not using
> os::malloc et al. A static buffer with dynamic fallback if needed might be
> okay - though if the static buffer is rarely big enough then that won't
> help.
>
> David
>
>
> On 8/06/2018 6:02 AM, Thomas Stüfe wrote:
>>
>> Hi Yasumasa,
>>
>> Sorry, but I have some general concerns about this:
>>
>> 1 Event logging, AFAIK, should be fast. Before, we had a pre-allocated
>> fixed sized character array into which the event text was written.
>> Now, we potentially malloc and realloc as a part of logging an event.
>>    It also should be robust, and malloc may fail in case of low-memory.
>>
>> 2 I do not really like the use of os::malloc etc there. Event logging
>> seems like a bottom component and I would hate to see circular
>> dependencies. os::malloc is a monster, it does UL logging, NMT tracing
>> etc...
>>
>> (1) is tough - would want to know what others think.
>> (2) could be easily solved by using raw malloc/realloc.
>>
>> One possibility to alleviate (1) would be to do a two buffer strategy.
>> A fixed sized dynamic member array, which is by definition
>> preallocated, for 99% of all cases. If that is not enough, fallback to
>> a dynamically allocated buffer.
>>
>> Code wise, at first cursory glance I think that the realloc strategy
>> could be done a bit smoother (e.g. realloc increase sizes by factor
>> 2). Also, I am not sure that FormatBufferDynamic would need to
>> implement all the method the standard FormatBuffer has? Seems an awful
>> lot of code duplication.
>>
>> Thanks & Best Regards, Thomas
>>
>>
>>
>>
>> On Thu, Jun 7, 2018 at 3:20 PM, Yasumasa Suenaga <yasuenag at gmail.com>
>> wrote:
>>>
>>> Thanks David!
>>> I filed it to JBS:
>>>
>>>    https://bugs.openjdk.java.net/browse/JDK-8204551
>>>
>>> I concern how we should fix for Windows.
>>> I'm waiting for opinion from you and other OpenJDK developers :-)
>>>
>>>
>>> Yasumasa
>>>
>>>
>>>
>>> On 2018/06/07 22:01, David Holmes wrote:
>>>>
>>>>
>>>> Sorry Yasumasa this one slipped through the cracks - as we say.
>>>>
>>>> By all means file a bug to record the issue. I'll try to take a look at
>>>> it
>>>> over the next couple of working days.
>>>>
>>>> David
>>>>
>>>> On 7/06/2018 10:49 PM, Yasumasa Suenaga wrote:
>>>>>
>>>>>
>>>>> Hi,
>>>>>
>>>>> Have you ever checked event strings in hs_err or VM.info?
>>>>> Please see as below!
>>>>>
>>>>>
>>>>> Yasumasa
>>>>>
>>>>>
>>>>> On 2018/05/01 9:41, Yasumasa Suenaga wrote:
>>>>>>
>>>>>>
>>>>>> Hi all,
>>>>>>
>>>>>> I found event description in hs_error log and VM.info dcmd are
>>>>>> trucated
>>>>>> as following:
>>>>>>
>>>>>> ```
>>>>>> Event: 1.977 Thread 0x00007f1720010800 Exception <a
>>>>>> 'java/lang/IncompatibleClassChangeError'{0x00000000d7a338f0}: Found
>>>>>> class
>>>>>> java.lang.Object, but interface was expected> (0x00000000d7a338f0)
>>>>>> thrown at
>>>>>>
>>>>>> [/scratch/opt/mach5/mesos/work_dir/slaves/9190d864-6621-4810-ba08-d8d8c75ba674-S702/framewo
>>>>>> ```
>>>>>>
>>>>>> I think we can fix it as this webrev. Is it acceptable?
>>>>>> If so, I will file it to JBS and send review request.
>>>>>>
>>>>>>     http://cr.openjdk.java.net/~ysuenaga/event-msg-truncated/
>>>>>>
>>>>>> This webrev shows event description as following:
>>>>>>
>>>>>> ```
>>>>>> Event: 3.660 Thread 0x00007fa174018800 Exception <a
>>>>>> 'java/lang/NoSuchMethodError'{0x00000000d778f878}:
>>>>>>
>>>>>> java.lang.invoke.DirectMethodHandle$Holder.invokeInterface(Ljava/lang/Object;Ljava/lang/Object;Ljava/lang/Object;)V>
>>>>>> (0x00000000d778f878) thrown at
>>>>>>
>>>>>> [/home/ysuenaga/OpenJDK/jdk/src/hotspot/share/interpreter/linkResolver.cpp,
>>>>>> line 755]
>>>>>> ```
>>>>>>
>>>>>> But I concern this change might not work when HotSpot is built with VS
>>>>>> 2013 or earlier.
>>>>>> This change uses vsnprintf() to get length of string, but _vscprintf()
>>>>>> will be used when older Visual Studio is used to build.
>>>>>>
>>>>>>
>>>>>> Thanks,
>>>>>>
>>>>>> Yasumasa
>>>>>>
>>>
>