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

Wed Nov 4 22:28:46 UTC 2015

Thanks, Coleen!
Rachel

On 11/4/2015 5:04 PM, Coleen Phillimore wrote:
> Agree. Thanks Marcus for the suggestion.   Rachel, I think this looks 
> great.  Thanks for all the work on this problem!  On to more logging!
>
> Coleen
>
> On 11/4/15 2:59 PM, Marcus Larsson wrote:
>> Looks good!
>>
>> Regards,
>> Marcus
>>
>> On 2015-11-04 20:49, Rachel Protacio wrote:
>>> Updated webrev with this fgets change: 
>>> http://cr.openjdk.java.net/~rprotacio/8139564.04/
>>>
>>> Passes JPRT tests.
>>>
>>> Thank you,
>>> Rachel
>>>
>>> On 11/4/2015 4:59 AM, Marcus Larsson wrote:
>>>> Hmm, I just noticed that the test doesn't null terminate the string 
>>>> it reads from file. Replacing the fgetc loop with a call to fgets 
>>>> should fix this.
>>>>
>>>> Regards,
>>>> Marcus
>>>>
>>>>
>>>> On 2015-11-04 10:49, Marcus Larsson wrote:
>>>>> 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
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>