Event descriptions are truncated in logs

Fri Jun 8 13:32:26 UTC 2018

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
>>>>>>>
>>>>
>>