[9] RFR(S): 8150441: CompileTask::print_impl() is broken after JDK-8146905

[David Holmes]

Hi Tobias,

On 23/02/2016 10:56 PM, Tobias Hartmann wrote:
> Hi David,
>
> thanks for having a look!
>
> On 23.02.2016 13:37, David Holmes wrote:
>> Hi Tobias,
>>
>> On 23/02/2016 8:19 PM, Tobias Hartmann wrote:
>>> Hi,
>>>
>>> please review the following patch.
>>>
>>> https://bugs.openjdk.java.net/browse/JDK-8150441
>>> http://cr.openjdk.java.net/~thartmann/8150441/webrev.00/
>>>
>>> The fix for JDK-8146905 [1] removed staticBufferStream and instead passes VMError::out/log to CompileTask::print_line_on_error() to print the current compile task if an error occurs. The problem is that fdStream VMError::out/log does not initialize the TimeStamp outputStream::_stamp and we hit the "must not be clear" assert in TimeStamp::milliseconds() which is called from CompileTask::print_impl(). Before, the TimeStamp was initialized in the staticBufferStream constructor [2].
>>
>> I find the original code difficult to follow.
>
> In the original code, the staticBufferStream constructor initializes "_stamp" which is inherited from outputStream [2].
>
>   staticBufferStream sbs(buffer, sizeof(buffer), &out);
>   report(&sbs, false);
>
> The staticBufferStream is passed on to
> -> VMError::report(outputStream* st, ..)
> -> CompileTask::print_line_on_error(..)
> -> CompileTask::print(..)
> -> CompileTask::print_impl(..)
> which then invokes st->time_stamp().milliseconds() with st->time_stamp()._counter == 0.
>
>>   The staticBufferStream did initialize its own stamp, but AFAICS that stamp is never used in relation to the wrapped outer-stream, so somehow that stamp must have been exposed through one of the methods that didn't delegate to the outer stream ??
>
> Yes, the stamp initialized by staticBufferStream is exposed through st->time_stamp() which does not delegate to the outer stream.

Got it - the timestamp was obtained directly from the stream instance, 
not the wrapped stream, and not used internally as I had assumed. Thanks.

>>> The time stamps should be explicitly initialized like we do in ostream_init(). I verified that my patch solves the problem.
>>
>> Why is the timestamp of a stream not initialized when the stream is constructed? Why are we deferring it until report_and_die() ?
>
> I'm not sure about this but I think we could eagerly initialize the timestamp in fdStream::fdStream() or outputStream::outputStream().

I was thinking more about when we construct and assign out/log rather 
than the actual constructors, but that may work too.  I think there is a 
potential bug with the proposed fix. We now have this "initialization" 
code at the start of report_and_die:

1102 {
1103   // Don't allocate large buffer on stack
1104   static char buffer[O_BUFLEN];
1105   out.set_scratch_buffer(buffer, sizeof(buffer));
1106   log.set_scratch_buffer(buffer, sizeof(buffer));
1107
1108   // Initialize time stamps to use the same base.
1109   out.time_stamp().update_to(1);
1110   log.time_stamp().update_to(1);

but this can be executed by more than one thread. The setting of the 
scratch buffer is idempotent so it doesn't matter if it is executed 
multiple times (though that makes it fragile as idempotency is not an 
obvious requirement). But the timestamp.update_to(1) will cause the 
timestamp to be reset multiple times. This may be benign but is probably 
not what is expected. I think this initialization either needs to be 
moved to when we initialize log/out or it needs to be moved into the 
branch were we only go for the first error:

1125   if (first_error_tid == -1 &&
1126       Atomic::cmpxchg_ptr(mytid, &first_error_tid, -1) == -1) {
1127
         // init time-stamp here

Thanks,
David

> Thanks,
> Tobias
>
>>
>> Thanks,
>> David
>>
>>> Thanks,
>>> Tobias
>>>
>>> [1] http://hg.openjdk.java.net/jdk9/hs-rt/hotspot/rev/64ba9950558b
>>> [2] http://hg.openjdk.java.net/jdk9/hs-rt/hotspot/rev/64ba9950558b#l1.102
>>>