8204551: Event descriptions are truncated in logs

Mon Jun 11 05:25:28 UTC 2018

Hi Yasumasa,

cc'ing Kim.

On 9/06/2018 12:38 AM, Yasumasa Suenaga wrote:
>> 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/

You deleted a lot of stuff that Kim put in the test so you'll need to 
explain why those invariants were either wrong, or are now no longer valid.

I'm unsure about changing the default buffer size from 256 to 1024. Plus 
these seem only used by the compiler so really the compiler folk should 
be having a say here.

prepare_buffer isn't checking for malloc/realloc failure.

I'd like someone familiar with NMT to comment as well as we're not using 
it to track the buffers. That was in response to comments from Thomas 
and I regarding os::* usage but now I'm unclear exactly when this code 
will get executed?

> 
> 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().

No idea. I don't think we can generally build JDK 11 with VS 2013.

Thanks,
David

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