RFR: 8138916: Logging write function does not allow for long enough messages

Mon Nov 2 18:03:42 UTC 2015

Thanks for the comments, Marcus. I've undone the "logtest" tag and 
instead created an InternalVMTest in log.cpp that writes the 
518-character string to a temporary file and looks for it there. Using 
"logging" tag in the "develop" level. Testing succeeds.

Webrev: http://cr.openjdk.java.net/~rprotacio/8139564.03/

Thank you,
Rachel

On 10/29/2015 6:35 AM, Marcus Larsson wrote:
> Hi,
>
> On 2015-10-28 21:59, Rachel Protacio wrote:
>> Including serviceability-dev. Recap:
>>
>> Summary: In logging/log.hpp, the logging vwrite function previously 
>> asserted that the buffer remains within 512 characters, which is
>> too short for logging message of non-pre-determined length, e.g. for 
>> vtable and itable function names. Now, the function resizes the buffer
>> to the appropriate length, asserting only that the resulting buffer 
>> is valid. Includes tag "logtest" to test that logging can print an 
>> output
>> of 518 characters.
>>
>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8138916.02
>> Bug: https://bugs.openjdk.java.net/browse/JDK-8138916
>
> I don't like that the test log message is included in the product, or 
> that a completely new tag is introduced for it.
>
> I think a much better approach would be to do the test logging in an 
> internal VM test, reusing the logging tag. This way it won't be logged 
> unless we are actually testing stuff, and we don't introduce a new 
> tag. Also it would look better if it were logged on develop level.
>
> Thanks,
> Marcus
>
>>
>> Includes own acceptance test, and passes JPRT and remote hotspot/test 
>> tests.
>>
>> Thank you,
>> Rachel
>>
>> On 10/28/2015 4:08 PM, Rachel Protacio wrote:
>>> Thanks for the review and all the feedback!
>>> Rachel
>>>
>>> On 10/28/2015 4:05 PM, Dmitry Samersoff wrote:
>>>> Rachel,
>>>>
>>>> Looks good for me!
>>>>
>>>> -Dmitry
>>>>
>>>> On 2015-10-28 20:50, Rachel Protacio wrote:
>>>>> Thank you both. I've removed the re-declaration and added 
>>>>> prefix_len to
>>>>> newbuf_len. As for line 115, that line is not for the sake of
>>>>> recalculating prefix_len, but for writing the prefix to the buffer.
>>>>>
>>>>> http://cr.openjdk.java.net/~rprotacio/8138916.02/
>>>>>
>>>>> Thanks,
>>>>> Rachel
>>>>>
>>>>> On 10/28/2015 12:27 PM, Coleen Phillimore wrote:
>>>>>> Dmitry, Thank you for reviewing and providing comments.  The second
>>>>>> version is better because of these things that I didn't notice until
>>>>>> you pointed it out.
>>>>>>
>>>>>> The malloc won't be frequent.  I think it'll be okay and follows 
>>>>>> other
>>>>>> coding patterns in the jvm.
>>>>>>
>>>>>> Thanks!
>>>>>> Coleen
>>>>>>
>>>>>> On 10/28/15 12:09 PM, Dmitry Samersoff wrote:
>>>>>>> Coleen,
>>>>>>>
>>>>>>> OK. I'm leaving it in good hands ;)
>>>>>>>
>>>>>>> -Dmitry
>>>>>>>
>>>>>>> On 2015-10-28 18:54, Coleen Phillimore wrote:
>>>>>>>> Hi, I'm also reviewing this. I think this looks good.   I don't 
>>>>>>>> think
>>>>>>>> the solution to allocate a static buffer is very nice because 
>>>>>>>> it still
>>>>>>>> has limits and we don't want to allocate something large on the 
>>>>>>>> stack.
>>>>>>>> The malloc case is the infrequent case.  If it becomes frequent 
>>>>>>>> we can
>>>>>>>> increase LogBufferSize from 512.
>>>>>>>>
>>>>>>>> I think 111 the assert is good because if the windows code is 
>>>>>>>> wrong (or
>>>>>>>> the vscprintf does something wrong an unexpected) we can catch the
>>>>>>>> error
>>>>>>>> with the assert before writing over memory.
>>>>>>>>
>>>>>>>> I agree 116 shouldn't redeclare 'ret'.
>>>>>>>>
>>>>>>>> Otherwise, I think it looks really good and I don't need to see 
>>>>>>>> another
>>>>>>>> revision.
>>>>>>>>
>>>>>>>> Thanks!
>>>>>>>> Coleen
>>>>>>>>
>>>>>>>>
>>>>>>>> On 10/28/15 11:40 AM, Dmitry Samersoff wrote:
>>>>>>>>> Rachel,
>>>>>>>>>
>>>>>>>>> On 2015-10-28 17:48, Rachel Protacio wrote:
>>>>>>>>>> Thank you for the comments, both Dmitry and Mikael. Replies 
>>>>>>>>>> inline.
>>>>>>>>>>
>>>>>>>>>> Modified webrev: 
>>>>>>>>>> http://cr.openjdk.java.net/~rprotacio/8138916.01/
>>>>>>>>> 111 Assert is never happens on Windows, so it's better to move 
>>>>>>>>> it to
>>>>>>>>> os_posix
>>>>>>>>>
>>>>>>>>> 113 newbuf_len doesn't account prefix_len
>>>>>>>>>
>>>>>>>>> 115 you may consider to use pre-calculated at ll. 108 prefix 
>>>>>>>>> rather
>>>>>>>>> than
>>>>>>>>> calculate it again.
>>>>>>>>>
>>>>>>>>> 116 int ret redefined it causes a warning.
>>>>>>>>>
>>>>>>>>> -Dmitry
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> (Retested and works fine.)
>>>>>>>>>>
>>>>>>>>>> On 10/27/2015 7:52 AM, Dmitry Samersoff wrote:
>>>>>>>>>>> Rachel,
>>>>>>>>>>>
>>>>>>>>>>> In worst case (windows, overflow) the code would parse 
>>>>>>>>>>> format string
>>>>>>>>>>> four times.
>>>>>>>>>> You're right. I've added a check. New amount of times 
>>>>>>>>>> vnsprintf() is
>>>>>>>>>> called:
>>>>>>>>>> posix, fits => 1
>>>>>>>>>> posix, overflow => 2
>>>>>>>>>> windows, fits => 1
>>>>>>>>>> windows, overflow => 3 (the best performance we can get)
>>>>>>>>>>
>>>>>>>>>>> Also NEW_C_HEAP_ARRAY takes a lock and might become a
>>>>>>>>>>> performance bottleneck.
>>>>>>>>>>>
>>>>>>>>>>> POSIX equivalent of _vscprintf(fmt, args) is vsnprintf(NULL, 
>>>>>>>>>>> 0, fmt,
>>>>>>>>>>> args)
>>>>>>>>>>>
>>>>>>>>>>> So it might be better to create os::log_vcprintf(fmt, args), 
>>>>>>>>>>> then
>>>>>>>>>>> write
>>>>>>>>>>> code at log.hpp as:
>>>>>>>>>>>
>>>>>>>>>>> int buf_len = os::log_vcprintf(fmt, args);
>>>>>>>>>>> assert(buf_len < 2*page_size, "Stack overflow in logging");
>>>>>>>>>>> char buf[buf_len];
>>>>>>>>>>> vsprintf(buf, fmt, args);
>>>>>>>>>> I don't think this would work anyway. A char[] needs a static 
>>>>>>>>>> size.
>>>>>>>>>> Thanks,
>>>>>>>>>> Rachel
>>>>>>>>>>> -Dmitry
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> On 2015-10-26 23:58, Rachel Protacio wrote:
>>>>>>>>>>>> Hello, all,
>>>>>>>>>>>>
>>>>>>>>>>>> Please review this fix to the faulty write function from the
>>>>>>>>>>>> Unified
>>>>>>>>>>>> Logging framework.
>>>>>>>>>>>>
>>>>>>>>>>>> Summary: In logging/log.hpp, the logging vwrite function 
>>>>>>>>>>>> previously
>>>>>>>>>>>> asserted that the buffer remains within 512 characters, 
>>>>>>>>>>>> which is
>>>>>>>>>>>> too
>>>>>>>>>>>> short for logging message of non-pre-determined length, 
>>>>>>>>>>>> e.g. for
>>>>>>>>>>>> vtable
>>>>>>>>>>>> and itable function names. Now, the function resizes the 
>>>>>>>>>>>> buffer
>>>>>>>>>>>> to the
>>>>>>>>>>>> appropriate length, asserting only that the resulting 
>>>>>>>>>>>> buffer is
>>>>>>>>>>>> valid.
>>>>>>>>>>>> Includes tag "logtest" to test that logging can print an 
>>>>>>>>>>>> output
>>>>>>>>>>>> of 518
>>>>>>>>>>>> characters.
>>>>>>>>>>>>
>>>>>>>>>>>> Open webrev:http://cr.openjdk.java.net/~rprotacio/8138916/
>>>>>>>>>>>> Bug:https://bugs.openjdk.java.net/browse/JDK-8138916
>>>>>>>>>>>>
>>>>>>>>>>>> Includes own acceptance test, and passes JPRT and remote
>>>>>>>>>>>> hotspot/test
>>>>>>>>>>>> tests.
>>>>>>>>>>>>
>>>>>>>>>>>> Thank you,
>>>>>>>>>>>> Rachel
>>>>
>>>
>>
>