RFR: JDK-8145315: VM crashes in print_task_time_stamps()

[Bengt Rutisson]

Thanks for the reviews, Jon and Jesper!

Bengt

On 2015-12-15 20:05, Jon Masamitsu wrote:
> Looks good.
>
> Jon
>
> On 12/15/2015 3:56 AM, Bengt Rutisson wrote:
>>
>> Hi everyone,
>>
>> Could I have a couple of reviews for this patch?
>>
>> http://cr.openjdk.java.net/~brutisso/8145315/webrev.00/
>> https://bugs.openjdk.java.net/browse/JDK-8145315
>>
>> The fix will make sure that the VM does not crash. But there is still 
>> an issue with that a task may not be printed if we run into the race 
>> that exist. This is a separate problem and outside the scope of this 
>> bug fix.
>>
>> From the bug report:
>>
>> The crash is due to an existing race condition in the ParallelGC. 
>> This race existed even before the new logging was introduced but we 
>> did not run with this logging enabled before.
>>
>> The test now runs with -Xlog:gc*=debug, which enables logging that 
>> was previously guarded by the PrintGCTaskTimeStamps flag.
>>
>> In the GCTaskThread::run() method we have this code:
>>
>>           GCTaskTimeStamp* time_stamp = 
>> time_stamp_at(_time_stamp_index++);
>>
>>           time_stamp->set_name(name);
>>           time_stamp->set_entry_time(entry_time);
>>           time_stamp->set_exit_time(timer.ticks());
>>
>>
>> And in GCTaskThread::print_task_time_stamps() we have this code:
>>
>> for(uint i=0; i<_time_stamp_index; i++) {
>>     GCTaskTimeStamp* time_stamp = time_stamp_at(i);
>>     log_debug(gc, task, time)("\t[ %s " JLONG_FORMAT " " JLONG_FORMAT 
>> " ]",
>>                               time_stamp->name(),
>>                               time_stamp->entry_time(),
>>                               time_stamp->exit_time());
>>   }
>>
>> The code in GCTaskThread::run() increments the _time_stamp_index 
>> value before setting the name, entry and exit times, which means that 
>> the code in GCTaskThread::print_task_time_stamps() can see the new 
>> value of _time_stamp_index before the name, entry and exit times have 
>> been set.
>>
>> I can reproduce this on Linux x64 with the following patch that 
>> introduces a sleep and an assert:
>>
>> diff --git a/src/share/vm/gc/parallel/gcTaskThread.cpp 
>> b/src/share/vm/gc/parallel/gcTaskThread.cpp
>> --- a/src/share/vm/gc/parallel/gcTaskThread.cpp
>> +++ b/src/share/vm/gc/parallel/gcTaskThread.cpp
>> @@ -83,6 +83,7 @@
>>    log_debug(gc, task, time)("GC-Thread %u entries: %d", id(), 
>> _time_stamp_index);
>>    for(uint i=0; i<_time_stamp_index; i++) {
>>      GCTaskTimeStamp* time_stamp = time_stamp_at(i);
>> + assert(time_stamp->name() != NULL, "NULL name");
>>      log_debug(gc, task, time)("\t[ %s " JLONG_FORMAT " " 
>> JLONG_FORMAT " ]",
>>                                time_stamp->name(),
>>                                time_stamp->entry_time(),
>> @@ -154,6 +155,12 @@
>>
>>            GCTaskTimeStamp* time_stamp = 
>> time_stamp_at(_time_stamp_index++);
>>
>> + if (os::random() % 100 == 0) {
>> + time_stamp->set_name(NULL);
>> + tty->print_cr("####### WAITING: %s", name);
>> + sleep(1);
>> + }
>> +
>>            time_stamp->set_name(name);
>>            time_stamp->set_entry_time(entry_time);
>>            time_stamp->set_exit_time(timer.ticks());
>>
>>
>> By updating the _time_stamp_index after we have set the other values 
>> we remove the crash:
>>
>> diff --git a/src/share/vm/gc/parallel/gcTaskThread.cpp 
>> b/src/share/vm/gc/parallel/gcTaskThread.cpp
>> --- a/src/share/vm/gc/parallel/gcTaskThread.cpp
>> +++ b/src/share/vm/gc/parallel/gcTaskThread.cpp
>> @@ -153,7 +153,7 @@
>>          if (log_is_enabled(Debug, gc, task, time)) {
>>            timer.update();
>>
>> - GCTaskTimeStamp* time_stamp = time_stamp_at(_time_stamp_index++);
>> + GCTaskTimeStamp* time_stamp = time_stamp_at(_time_stamp_index);
>>
>>            if (os::random() % 100 == 0) {
>>              time_stamp->set_name(NULL);
>> @@ -164,6 +164,7 @@
>>            time_stamp->set_name(name);
>>            time_stamp->set_entry_time(entry_time);
>>            time_stamp->set_exit_time(timer.ticks());
>> + _time_stamp_index++;
>>          }
>>        } else {
>>          // idle tasks complete outside the normal accounting
>>
>>
>> Running with the first patch asserts every time. Adding the second 
>> patch does not hit the assert.
>