8204551: Event descriptions are truncated in logs

Mon Jun 11 12:49:34 UTC 2018

Hi,

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

My proposal calls vsnprintf() with NULL and 0 to get buffer size.
test_os.cpp checks these arguments, and it will fail if these values are passed.
So I remove related code from test_os.cpp .

>> prepare_buffer isn't checking for malloc/realloc failure.

Thanks, I will fix it.

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

If we need to continue to use VS 2013, we need to be another approach for this issue.

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

How many buffers should be allocated for it? And how we manage if it is not enough to store log strings?
I'm unclear it.

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

My proposal use vsnprintf() to estimate buffer size.
So I change related code.

Thanks,

Yasumasa

On 2018/06/11 15:42, Thomas Stüfe wrote:
> 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
>>>>>>>>>>>
>>>>>>>>
>>>>>>
>>