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

[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.