8204551: Event descriptions are truncated in logs

Mon Jun 11 06:42:15 UTC 2018

Hi,

while I appreciate the effort put into this (the problem is real), I
am not happy with the way this patch is going.

I think 1024 bytes are way too excessive, especially since most of
this memory will effectively be wasted. I would prefer a solution
which is more memory conservative while also minimizing the chance of
truncating event lines. I also still do not like the malloc in here.
Lets discuss this further, yes?

How about this:

Use a pre-allocated static char array. Organize a ring buffer atop of
it. Give it "alloc" and "free" methods and use those to satisfy memory
requirements for the event text if the event is larger than the record
local buffer. Leave the size of the record local buffer at 256, or
make it even smaller - we may have to experiment.

With this proposal we still might see - rarely - truncated event
lines. This depends on the sizing of the ring buffer and on the
record-local buffers. But it would use the memory much more
efficiently, and it does not need to allocate memory at runtime at
all.

What do you guys think?

---
as for the change: I do not understand why the change to jio_vsnprintf
is necessary, nor the changes to the gtests.

..Thomas

On Mon, Jun 11, 2018 at 7:25 AM, David Holmes <david.holmes at oracle.com> wrote:
> 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
>>>>>>>>>>
>>>>>>>
>>>>>
>