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

[Jon Masamitsu]

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.