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

[Jesper Wilhelmsson]

Looks good!
/Jesper

Den 15/12/15 kl. 12:56, skrev Bengt Rutisson:
>
> 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.