[9] RFR(S): 8153527: break_tty_lock_for_safepoint causes "assert(false) failed: bad tag in log" and broken compile log

[Nils Eliasson]

Hi,

Thanks for the help,

I got it to work, and added NoSafePointVerifiers to make sure I hadn't 
missed anything. Then after many test iterations it failed again. It 
didn't fail on the NSPV, but in dump_asm we blocked on a VM entry to get 
a ciSymbol->as_utf8. Now I am considering if I should direct dump_asm to 
the temporary buffer too, or relax the tag checks in the xml and accept 
that the output may need to be sorted by writer-thread before use. The 
output looks like:

<writer id=1/>
<print_optoassembly>
...
releases tty when blocking on a safepoint
<writer id=2/>
<print_nmethod>
...
<writer id=1/>         // back again after safepoint writing without 
ttylock now.
</print_optoassembly>  // Here we fail on an assert today when we expect 
a closing print_nmethod tag
<writer id=2/>
</print_nmethod>

This is malformed xml but has enough information to be reconstructed. 
Would this be an acceptable output?

Regards,
Nils


On 2016-04-18 19:30, Vladimir Kozlov wrote:
> tty would have the same problem but it use C_HEAP to allocate:
>
>     defaultStream::instance = new(ResourceObj::C_HEAP, mtInternal) 
> defaultStream();
>
> Please, look if you can do something similar.
>
> Thanks,
> Vladimir
>
> On 4/18/16 4:24 AM, Nils Eliasson wrote:
>> Resizeable is better, but then we assert on expanding the stringbuffer
>> while being under a different ResourceMark.
>>
>> Regards,
>> Nils
>>
>> On 2016-04-15 19:44, Vladimir Kozlov wrote:
>>> Use resizable stream:
>>>
>>> stringStream(size_t initial_bufsize = 256);
>>>
>>> 1024 may not be enough.
>>>
>>> Thanks,
>>> Vladimir
>>>
>>> On 4/15/16 8:10 AM, Nils Eliasson wrote:
>>>> Hi,
>>>>
>>>> Please review this fix of print opto_assembly.
>>>>
>>>> Summary:
>>>> The compilelog can get corrupted and the VM may assert on "failed:
>>>> bad tag in log".
>>>>
>>>> When printing assembly in output.cpp we first take the ttylock, print
>>>> the head and then the method metadata. However the
>>>> metadata printing makes a vm entry and may block for a safepoint and
>>>> will then release the lock
>>>> (break_tty_lock_for_safepoint). After that some of the other compiler
>>>> thread that haven't safepointed will take the lock
>>>> and the broken log will be a fact when the safepoint is over and the
>>>> first thread starts logging again.
>>>>
>>>> Solution:
>>>> Print the method metadata to a temporary buffer, then take the tty 
>>>> lock.
>>>>
>>>> Testing:
>>>> Repro from bug stops failing.
>>>> Running :hotspot_all
>>>> (http://jdash.se.oracle.com/rbt/rbt-nils.eliasson-compiler_control-20160415-1508-10854) 
>>>>
>>>>
>>>>
>>>> Bug: https://bugs.openjdk.java.net/browse/JDK-8153527
>>>> Webrev: http://cr.openjdk.java.net/~neliasso/8153527/webrev.01/
>>>>
>>>> Regards,
>>>> Nils Eliasson
>>