8204551: Event descriptions are truncated in logs

Fri Jun 8 14:38:52 UTC 2018

> I pushed this change to JDK-8204551 branch on submit repo, but I got error report from Mach 5. It says this change was failed on gtest/GTestWrapper.java (mach5-one-ysuenaga-JDK-8204551-20180608-0514-25665).
> I tried to reproduce it on my Linux box, but I could not yet.

I found the problem in test_os.cpp for GTest.
I fixed it and pushed to submit repo:

   http://hg.openjdk.java.net/jdk/submit/rev/889789ea0f6e

webrev is here:

   http://cr.openjdk.java.net/~ysuenaga/JDK-8204551/webrev.01/

I want to know this change works correct if HotSpot is built with VS 2013 or earlier.
This change depends on return value from vsnprintf().

Thanks,

Yasumasa

On 2018/06/08 22:32, Yasumasa Suenaga wrote:
> Hi Thomas, David,
> 
> Thank you for your reply.
> I uploaded new webrev:
> 
>    http://cr.openjdk.java.net/~ysuenaga/JDK-8204551/webrev.00/
> 
> I added new class `FormatBufferEx` which extends buffer through malloc() if buffer size is not enough.
> And I extended buffer size to 1024 from 256.
> 
> I pushed this change to JDK-8204551 branch on submit repo, but I got error report from Mach 5. It says this change was failed on gtest/GTestWrapper.java (mach5-one-ysuenaga-JDK-8204551-20180608-0514-25665).
> I tried to reproduce it on my Linux box, but I could not yet.
> 
> 
> Yasumasa
> 
> 
> On 2018/06/08 14:33, Thomas Stüfe wrote:
>> 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
>>>>>>>>
>>>>>
>>>