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

Wed Nov 4 09:49:41 UTC 2015

Looks good, thank you for fixing this!

Regards,
Marcus

On 2015-11-02 19:03, Rachel Protacio wrote:
> 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
>>>>>
>>>>
>>>
>>
>