src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp

Print this page
rev 4029 : 8007221: G1: concurrent phase durations do not state the time units ("secs")
Summary: Add timer units to concurrent marking phases where the units were missing.
Reviewed-by:


 100       // make sure that we do not join the STS until the root regions
 101       // have been scanned. If we did then it's possible that a
 102       // subsequent GC could block us from joining the STS and proceed
 103       // without the root regions have been scanned which would be a
 104       // correctness issue.
 105 
 106       double scan_start = os::elapsedTime();
 107       if (!cm()->has_aborted()) {
 108         if (G1Log::fine()) {
 109           gclog_or_tty->date_stamp(PrintGCDateStamps);
 110           gclog_or_tty->stamp(PrintGCTimeStamps);
 111           gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
 112         }
 113 
 114         _cm->scanRootRegions();
 115 
 116         double scan_end = os::elapsedTime();
 117         if (G1Log::fine()) {
 118           gclog_or_tty->date_stamp(PrintGCDateStamps);
 119           gclog_or_tty->stamp(PrintGCTimeStamps);
 120           gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf]",
 121                                  scan_end - scan_start);
 122         }
 123       }
 124 
 125       double mark_start_sec = os::elapsedTime();
 126       if (G1Log::fine()) {
 127         gclog_or_tty->date_stamp(PrintGCDateStamps);
 128         gclog_or_tty->stamp(PrintGCTimeStamps);
 129         gclog_or_tty->print_cr("[GC concurrent-mark-start]");
 130       }
 131 
 132       int iter = 0;
 133       do {
 134         iter++;
 135         if (!cm()->has_aborted()) {
 136           _cm->markFromRoots();
 137         }
 138 
 139         double mark_end_time = os::elapsedVTime();
 140         double mark_end_sec = os::elapsedTime();
 141         _vtime_mark_accum += (mark_end_time - cycle_start);
 142         if (!cm()->has_aborted()) {
 143           if (g1_policy->adaptive_young_list_length()) {
 144             double now = os::elapsedTime();
 145             double remark_prediction_ms = g1_policy->predict_remark_time_ms();
 146             jlong sleep_time_ms = mmu_tracker->when_ms(now, remark_prediction_ms);
 147             os::sleep(current_thread, sleep_time_ms, false);
 148           }
 149 
 150           if (G1Log::fine()) {
 151             gclog_or_tty->date_stamp(PrintGCDateStamps);
 152             gclog_or_tty->stamp(PrintGCTimeStamps);
 153             gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf sec]",
 154                                       mark_end_sec - mark_start_sec);
 155           }
 156 
 157           CMCheckpointRootsFinalClosure final_cl(_cm);
 158           sprintf(verbose_str, "GC remark");
 159           VM_CGC_Operation op(&final_cl, verbose_str, true /* needs_pll */);
 160           VMThread::execute(&op);
 161         }
 162         if (cm()->restart_for_overflow()) {
 163           if (G1TraceMarkStackOverflow) {
 164             gclog_or_tty->print_cr("Restarting conc marking because of MS overflow "
 165                                    "in remark (restart #%d).", iter);
 166           }
 167           if (G1Log::fine()) {
 168             gclog_or_tty->date_stamp(PrintGCDateStamps);
 169             gclog_or_tty->stamp(PrintGCTimeStamps);
 170             gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]");
 171           }
 172         }
 173       } while (cm()->restart_for_overflow());


 217         }
 218 
 219         // Now do the concurrent cleanup operation.
 220         _cm->completeCleanup();
 221 
 222         // Notify anyone who's waiting that there are no more free
 223         // regions coming. We have to do this before we join the STS
 224         // (in fact, we should not attempt to join the STS in the
 225         // interval between finishing the cleanup pause and clearing
 226         // the free_regions_coming flag) otherwise we might deadlock:
 227         // a GC worker could be blocked waiting for the notification
 228         // whereas this thread will be blocked for the pause to finish
 229         // while it's trying to join the STS, which is conditional on
 230         // the GC workers finishing.
 231         g1h->reset_free_regions_coming();
 232 
 233         double cleanup_end_sec = os::elapsedTime();
 234         if (G1Log::fine()) {
 235           gclog_or_tty->date_stamp(PrintGCDateStamps);
 236           gclog_or_tty->stamp(PrintGCTimeStamps);
 237           gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf]",
 238                                  cleanup_end_sec - cleanup_start_sec);
 239         }
 240       }
 241       guarantee(cm()->cleanup_list_is_empty(),
 242                 "at this point there should be no regions on the cleanup list");
 243 
 244       // There is a tricky race before recording that the concurrent
 245       // cleanup has completed and a potential Full GC starting around
 246       // the same time. We want to make sure that the Full GC calls
 247       // abort() on concurrent mark after
 248       // record_concurrent_mark_cleanup_completed(), since abort() is
 249       // the method that will reset the concurrent mark state. If we
 250       // end up calling record_concurrent_mark_cleanup_completed()
 251       // after abort() then we might incorrectly undo some of the work
 252       // abort() did. Checking the has_aborted() flag after joining
 253       // the STS allows the correct ordering of the two methods. There
 254       // are two scenarios:
 255       //
 256       // a) If we reach here before the Full GC, the fact that we have
 257       // joined the STS means that the Full GC cannot start until we




 100       // make sure that we do not join the STS until the root regions
 101       // have been scanned. If we did then it's possible that a
 102       // subsequent GC could block us from joining the STS and proceed
 103       // without the root regions have been scanned which would be a
 104       // correctness issue.
 105 
 106       double scan_start = os::elapsedTime();
 107       if (!cm()->has_aborted()) {
 108         if (G1Log::fine()) {
 109           gclog_or_tty->date_stamp(PrintGCDateStamps);
 110           gclog_or_tty->stamp(PrintGCTimeStamps);
 111           gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
 112         }
 113 
 114         _cm->scanRootRegions();
 115 
 116         double scan_end = os::elapsedTime();
 117         if (G1Log::fine()) {
 118           gclog_or_tty->date_stamp(PrintGCDateStamps);
 119           gclog_or_tty->stamp(PrintGCTimeStamps);
 120           gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf secs]",
 121                                  scan_end - scan_start);
 122         }
 123       }
 124 
 125       double mark_start_sec = os::elapsedTime();
 126       if (G1Log::fine()) {
 127         gclog_or_tty->date_stamp(PrintGCDateStamps);
 128         gclog_or_tty->stamp(PrintGCTimeStamps);
 129         gclog_or_tty->print_cr("[GC concurrent-mark-start]");
 130       }
 131 
 132       int iter = 0;
 133       do {
 134         iter++;
 135         if (!cm()->has_aborted()) {
 136           _cm->markFromRoots();
 137         }
 138 
 139         double mark_end_time = os::elapsedVTime();
 140         double mark_end_sec = os::elapsedTime();
 141         _vtime_mark_accum += (mark_end_time - cycle_start);
 142         if (!cm()->has_aborted()) {
 143           if (g1_policy->adaptive_young_list_length()) {
 144             double now = os::elapsedTime();
 145             double remark_prediction_ms = g1_policy->predict_remark_time_ms();
 146             jlong sleep_time_ms = mmu_tracker->when_ms(now, remark_prediction_ms);
 147             os::sleep(current_thread, sleep_time_ms, false);
 148           }
 149 
 150           if (G1Log::fine()) {
 151             gclog_or_tty->date_stamp(PrintGCDateStamps);
 152             gclog_or_tty->stamp(PrintGCTimeStamps);
 153             gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf secs]",
 154                                       mark_end_sec - mark_start_sec);
 155           }
 156 
 157           CMCheckpointRootsFinalClosure final_cl(_cm);
 158           sprintf(verbose_str, "GC remark");
 159           VM_CGC_Operation op(&final_cl, verbose_str, true /* needs_pll */);
 160           VMThread::execute(&op);
 161         }
 162         if (cm()->restart_for_overflow()) {
 163           if (G1TraceMarkStackOverflow) {
 164             gclog_or_tty->print_cr("Restarting conc marking because of MS overflow "
 165                                    "in remark (restart #%d).", iter);
 166           }
 167           if (G1Log::fine()) {
 168             gclog_or_tty->date_stamp(PrintGCDateStamps);
 169             gclog_or_tty->stamp(PrintGCTimeStamps);
 170             gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]");
 171           }
 172         }
 173       } while (cm()->restart_for_overflow());


 217         }
 218 
 219         // Now do the concurrent cleanup operation.
 220         _cm->completeCleanup();
 221 
 222         // Notify anyone who's waiting that there are no more free
 223         // regions coming. We have to do this before we join the STS
 224         // (in fact, we should not attempt to join the STS in the
 225         // interval between finishing the cleanup pause and clearing
 226         // the free_regions_coming flag) otherwise we might deadlock:
 227         // a GC worker could be blocked waiting for the notification
 228         // whereas this thread will be blocked for the pause to finish
 229         // while it's trying to join the STS, which is conditional on
 230         // the GC workers finishing.
 231         g1h->reset_free_regions_coming();
 232 
 233         double cleanup_end_sec = os::elapsedTime();
 234         if (G1Log::fine()) {
 235           gclog_or_tty->date_stamp(PrintGCDateStamps);
 236           gclog_or_tty->stamp(PrintGCTimeStamps);
 237           gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf secs]",
 238                                  cleanup_end_sec - cleanup_start_sec);
 239         }
 240       }
 241       guarantee(cm()->cleanup_list_is_empty(),
 242                 "at this point there should be no regions on the cleanup list");
 243 
 244       // There is a tricky race before recording that the concurrent
 245       // cleanup has completed and a potential Full GC starting around
 246       // the same time. We want to make sure that the Full GC calls
 247       // abort() on concurrent mark after
 248       // record_concurrent_mark_cleanup_completed(), since abort() is
 249       // the method that will reset the concurrent mark state. If we
 250       // end up calling record_concurrent_mark_cleanup_completed()
 251       // after abort() then we might incorrectly undo some of the work
 252       // abort() did. Checking the has_aborted() flag after joining
 253       // the STS allows the correct ordering of the two methods. There
 254       // are two scenarios:
 255       //
 256       // a) If we reach here before the Full GC, the fact that we have
 257       // joined the STS means that the Full GC cannot start until we