1.1 --- a/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Fri Jun 07 09:33:01 2013 -0700
1.2 +++ b/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp Mon Jun 10 11:30:51 2013 +0200
1.3 @@ -37,8 +37,12 @@
1.4 #include "gc_implementation/concurrentMarkSweep/vmCMSOperations.hpp"
1.5 #include "gc_implementation/parNew/parNewGeneration.hpp"
1.6 #include "gc_implementation/shared/collectorCounters.hpp"
1.7 +#include "gc_implementation/shared/gcTimer.hpp"
1.8 +#include "gc_implementation/shared/gcTrace.hpp"
1.9 +#include "gc_implementation/shared/gcTraceTime.hpp"
1.10 #include "gc_implementation/shared/isGCActiveMark.hpp"
1.11 #include "gc_interface/collectedHeap.inline.hpp"
1.12 +#include "memory/allocation.hpp"
1.13 #include "memory/cardTableRS.hpp"
1.14 #include "memory/collectorPolicy.hpp"
1.15 #include "memory/gcLocker.inline.hpp"
1.16 @@ -60,7 +64,8 @@
1.17
1.18 // statics
1.19 CMSCollector* ConcurrentMarkSweepGeneration::_collector = NULL;
1.20 -bool CMSCollector::_full_gc_requested = false;
1.21 +bool CMSCollector::_full_gc_requested = false;
1.22 +GCCause::Cause CMSCollector::_full_gc_cause = GCCause::_no_gc;
1.23
1.24 //////////////////////////////////////////////////////////////////
1.25 // In support of CMS/VM thread synchronization
1.26 @@ -591,7 +596,10 @@
1.27 _concurrent_cycles_since_last_unload(0),
1.28 _roots_scanning_options(0),
1.29 _inter_sweep_estimate(CMS_SweepWeight, CMS_SweepPadding),
1.30 - _intra_sweep_estimate(CMS_SweepWeight, CMS_SweepPadding)
1.31 + _intra_sweep_estimate(CMS_SweepWeight, CMS_SweepPadding),
1.32 + _gc_tracer_cm(new (ResourceObj::C_HEAP, mtGC) CMSTracer()),
1.33 + _gc_timer_cm(new (ResourceObj::C_HEAP, mtGC) ConcurrentGCTimer()),
1.34 + _cms_start_registered(false)
1.35 {
1.36 if (ExplicitGCInvokesConcurrentAndUnloadsClasses) {
1.37 ExplicitGCInvokesConcurrent = true;
1.38 @@ -1676,18 +1684,38 @@
1.39 _full_gcs_since_conc_gc++;
1.40 }
1.41
1.42 -void CMSCollector::request_full_gc(unsigned int full_gc_count) {
1.43 +void CMSCollector::request_full_gc(unsigned int full_gc_count, GCCause::Cause cause) {
1.44 GenCollectedHeap* gch = GenCollectedHeap::heap();
1.45 unsigned int gc_count = gch->total_full_collections();
1.46 if (gc_count == full_gc_count) {
1.47 MutexLockerEx y(CGC_lock, Mutex::_no_safepoint_check_flag);
1.48 _full_gc_requested = true;
1.49 + _full_gc_cause = cause;
1.50 CGC_lock->notify(); // nudge CMS thread
1.51 } else {
1.52 assert(gc_count > full_gc_count, "Error: causal loop");
1.53 }
1.54 }
1.55
1.56 +bool CMSCollector::is_external_interruption() {
1.57 + GCCause::Cause cause = GenCollectedHeap::heap()->gc_cause();
1.58 + return GCCause::is_user_requested_gc(cause) ||
1.59 + GCCause::is_serviceability_requested_gc(cause);
1.60 +}
1.61 +
1.62 +void CMSCollector::report_concurrent_mode_interruption() {
1.63 + if (is_external_interruption()) {
1.64 + if (PrintGCDetails) {
1.65 + gclog_or_tty->print(" (concurrent mode interrupted)");
1.66 + }
1.67 + } else {
1.68 + if (PrintGCDetails) {
1.69 + gclog_or_tty->print(" (concurrent mode failure)");
1.70 + }
1.71 + _gc_tracer_cm->report_concurrent_mode_failure();
1.72 + }
1.73 +}
1.74 +
1.75
1.76 // The foreground and background collectors need to coordinate in order
1.77 // to make sure that they do not mutually interfere with CMS collections.
1.78 @@ -1845,14 +1873,8 @@
1.79 }
1.80 )
1.81
1.82 - if (PrintGCDetails && first_state > Idling) {
1.83 - GCCause::Cause cause = GenCollectedHeap::heap()->gc_cause();
1.84 - if (GCCause::is_user_requested_gc(cause) ||
1.85 - GCCause::is_serviceability_requested_gc(cause)) {
1.86 - gclog_or_tty->print(" (concurrent mode interrupted)");
1.87 - } else {
1.88 - gclog_or_tty->print(" (concurrent mode failure)");
1.89 - }
1.90 + if (first_state > Idling) {
1.91 + report_concurrent_mode_interruption();
1.92 }
1.93
1.94 set_did_compact(should_compact);
1.95 @@ -1868,6 +1890,10 @@
1.96 // Reference objects are active.
1.97 ref_processor()->clean_up_discovered_references();
1.98
1.99 + if (first_state > Idling) {
1.100 + save_heap_summary();
1.101 + }
1.102 +
1.103 do_compaction_work(clear_all_soft_refs);
1.104
1.105 // Has the GC time limit been exceeded?
1.106 @@ -1971,7 +1997,14 @@
1.107 // a mark-sweep-compact.
1.108 void CMSCollector::do_compaction_work(bool clear_all_soft_refs) {
1.109 GenCollectedHeap* gch = GenCollectedHeap::heap();
1.110 - TraceTime t("CMS:MSC ", PrintGCDetails && Verbose, true, gclog_or_tty);
1.111 +
1.112 + STWGCTimer* gc_timer = GenMarkSweep::gc_timer();
1.113 + gc_timer->register_gc_start(os::elapsed_counter());
1.114 +
1.115 + SerialOldTracer* gc_tracer = GenMarkSweep::gc_tracer();
1.116 + gc_tracer->report_gc_start(gch->gc_cause(), gc_timer->gc_start());
1.117 +
1.118 + GCTraceTime t("CMS:MSC ", PrintGCDetails && Verbose, true, NULL);
1.119 if (PrintGC && Verbose && !(GCCause::is_user_requested_gc(gch->gc_cause()))) {
1.120 gclog_or_tty->print_cr("Compact ConcurrentMarkSweepGeneration after %d "
1.121 "collections passed to foreground collector", _full_gcs_since_conc_gc);
1.122 @@ -2062,6 +2095,10 @@
1.123 size_policy()->msc_collection_end(gch->gc_cause());
1.124 }
1.125
1.126 + gc_timer->register_gc_end(os::elapsed_counter());
1.127 +
1.128 + gc_tracer->report_gc_end(gc_timer->gc_end(), gc_timer->time_partitions());
1.129 +
1.130 // For a mark-sweep-compact, compute_new_size() will be called
1.131 // in the heap's do_collection() method.
1.132 }
1.133 @@ -2093,7 +2130,7 @@
1.134 // required.
1.135 _collectorState = FinalMarking;
1.136 }
1.137 - collect_in_foreground(clear_all_soft_refs);
1.138 + collect_in_foreground(clear_all_soft_refs, GenCollectedHeap::heap()->gc_cause());
1.139
1.140 // For a mark-sweep, compute_new_size() will be called
1.141 // in the heap's do_collection() method.
1.142 @@ -2153,7 +2190,7 @@
1.143 // one "collect" method between the background collector and the foreground
1.144 // collector but the if-then-else required made it cleaner to have
1.145 // separate methods.
1.146 -void CMSCollector::collect_in_background(bool clear_all_soft_refs) {
1.147 +void CMSCollector::collect_in_background(bool clear_all_soft_refs, GCCause::Cause cause) {
1.148 assert(Thread::current()->is_ConcurrentGC_thread(),
1.149 "A CMS asynchronous collection is only allowed on a CMS thread.");
1.150
1.151 @@ -2172,6 +2209,7 @@
1.152 } else {
1.153 assert(_collectorState == Idling, "Should be idling before start.");
1.154 _collectorState = InitialMarking;
1.155 + register_gc_start(cause);
1.156 // Reset the expansion cause, now that we are about to begin
1.157 // a new cycle.
1.158 clear_expansion_cause();
1.159 @@ -2184,6 +2222,7 @@
1.160 // ensuing concurrent GC cycle.
1.161 update_should_unload_classes();
1.162 _full_gc_requested = false; // acks all outstanding full gc requests
1.163 + _full_gc_cause = GCCause::_no_gc;
1.164 // Signal that we are about to start a collection
1.165 gch->increment_total_full_collections(); // ... starting a collection cycle
1.166 _collection_count_start = gch->total_full_collections();
1.167 @@ -2263,7 +2302,6 @@
1.168 {
1.169 ReleaseForegroundGC x(this);
1.170 stats().record_cms_begin();
1.171 -
1.172 VM_CMS_Initial_Mark initial_mark_op(this);
1.173 VMThread::execute(&initial_mark_op);
1.174 }
1.175 @@ -2343,6 +2381,7 @@
1.176 CMSTokenSync z(true); // not strictly needed.
1.177 if (_collectorState == Resizing) {
1.178 compute_new_size();
1.179 + save_heap_summary();
1.180 _collectorState = Resetting;
1.181 } else {
1.182 assert(_collectorState == Idling, "The state should only change"
1.183 @@ -2401,7 +2440,39 @@
1.184 }
1.185 }
1.186
1.187 -void CMSCollector::collect_in_foreground(bool clear_all_soft_refs) {
1.188 +void CMSCollector::register_foreground_gc_start(GCCause::Cause cause) {
1.189 + if (!_cms_start_registered) {
1.190 + register_gc_start(cause);
1.191 + }
1.192 +}
1.193 +
1.194 +void CMSCollector::register_gc_start(GCCause::Cause cause) {
1.195 + _cms_start_registered = true;
1.196 + _gc_timer_cm->register_gc_start(os::elapsed_counter());
1.197 + _gc_tracer_cm->report_gc_start(cause, _gc_timer_cm->gc_start());
1.198 +}
1.199 +
1.200 +void CMSCollector::register_gc_end() {
1.201 + if (_cms_start_registered) {
1.202 + report_heap_summary(GCWhen::AfterGC);
1.203 +
1.204 + _gc_timer_cm->register_gc_end(os::elapsed_counter());
1.205 + _gc_tracer_cm->report_gc_end(_gc_timer_cm->gc_end(), _gc_timer_cm->time_partitions());
1.206 + _cms_start_registered = false;
1.207 + }
1.208 +}
1.209 +
1.210 +void CMSCollector::save_heap_summary() {
1.211 + GenCollectedHeap* gch = GenCollectedHeap::heap();
1.212 + _last_heap_summary = gch->create_heap_summary();
1.213 + _last_metaspace_summary = gch->create_metaspace_summary();
1.214 +}
1.215 +
1.216 +void CMSCollector::report_heap_summary(GCWhen::Type when) {
1.217 + _gc_tracer_cm->report_gc_heap_summary(when, _last_heap_summary, _last_metaspace_summary);
1.218 +}
1.219 +
1.220 +void CMSCollector::collect_in_foreground(bool clear_all_soft_refs, GCCause::Cause cause) {
1.221 assert(_foregroundGCIsActive && !_foregroundGCShouldWait,
1.222 "Foreground collector should be waiting, not executing");
1.223 assert(Thread::current()->is_VM_thread(), "A foreground collection"
1.224 @@ -2409,8 +2480,8 @@
1.225 assert(ConcurrentMarkSweepThread::vm_thread_has_cms_token(),
1.226 "VM thread should have CMS token");
1.227
1.228 - NOT_PRODUCT(TraceTime t("CMS:MS (foreground) ", PrintGCDetails && Verbose,
1.229 - true, gclog_or_tty);)
1.230 + NOT_PRODUCT(GCTraceTime t("CMS:MS (foreground) ", PrintGCDetails && Verbose,
1.231 + true, NULL);)
1.232 if (UseAdaptiveSizePolicy) {
1.233 size_policy()->ms_collection_begin();
1.234 }
1.235 @@ -2434,6 +2505,7 @@
1.236 }
1.237 switch (_collectorState) {
1.238 case InitialMarking:
1.239 + register_foreground_gc_start(cause);
1.240 init_mark_was_synchronous = true; // fact to be exploited in re-mark
1.241 checkpointRootsInitial(false);
1.242 assert(_collectorState == Marking, "Collector state should have changed"
1.243 @@ -2482,6 +2554,7 @@
1.244 GenCollectedHeap::heap()->total_collections() >= VerifyGCStartAt) {
1.245 Universe::verify("Verify before reset: ");
1.246 }
1.247 + save_heap_summary();
1.248 reset(false);
1.249 assert(_collectorState == Idling, "Collector state should "
1.250 "have changed");
1.251 @@ -3504,6 +3577,9 @@
1.252 check_correct_thread_executing();
1.253 TraceCMSMemoryManagerStats tms(_collectorState,GenCollectedHeap::heap()->gc_cause());
1.254
1.255 + save_heap_summary();
1.256 + report_heap_summary(GCWhen::BeforeGC);
1.257 +
1.258 ReferenceProcessor* rp = ref_processor();
1.259 SpecializationStats::clear();
1.260 assert(_restart_addr == NULL, "Control point invariant");
1.261 @@ -3549,8 +3625,8 @@
1.262 // CMS collection cycle.
1.263 setup_cms_unloading_and_verification_state();
1.264
1.265 - NOT_PRODUCT(TraceTime t("\ncheckpointRootsInitialWork",
1.266 - PrintGCDetails && Verbose, true, gclog_or_tty);)
1.267 + NOT_PRODUCT(GCTraceTime t("\ncheckpointRootsInitialWork",
1.268 + PrintGCDetails && Verbose, true, _gc_timer_cm);)
1.269 if (UseAdaptiveSizePolicy) {
1.270 size_policy()->checkpoint_roots_initial_begin();
1.271 }
1.272 @@ -4542,8 +4618,10 @@
1.273 // The code in this method may need further
1.274 // tweaking for better performance and some restructuring
1.275 // for cleaner interfaces.
1.276 + GCTimer *gc_timer = NULL; // Currently not tracing concurrent phases
1.277 rp->preclean_discovered_references(
1.278 - rp->is_alive_non_header(), &keep_alive, &complete_trace, &yield_cl);
1.279 + rp->is_alive_non_header(), &keep_alive, &complete_trace, &yield_cl,
1.280 + gc_timer);
1.281 }
1.282
1.283 if (clean_survivor) { // preclean the active survivor space(s)
1.284 @@ -4885,8 +4963,8 @@
1.285 // Temporarily set flag to false, GCH->do_collection will
1.286 // expect it to be false and set to true
1.287 FlagSetting fl(gch->_is_gc_active, false);
1.288 - NOT_PRODUCT(TraceTime t("Scavenge-Before-Remark",
1.289 - PrintGCDetails && Verbose, true, gclog_or_tty);)
1.290 + NOT_PRODUCT(GCTraceTime t("Scavenge-Before-Remark",
1.291 + PrintGCDetails && Verbose, true, _gc_timer_cm);)
1.292 int level = _cmsGen->level() - 1;
1.293 if (level >= 0) {
1.294 gch->do_collection(true, // full (i.e. force, see below)
1.295 @@ -4915,7 +4993,7 @@
1.296 void CMSCollector::checkpointRootsFinalWork(bool asynch,
1.297 bool clear_all_soft_refs, bool init_mark_was_synchronous) {
1.298
1.299 - NOT_PRODUCT(TraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, gclog_or_tty);)
1.300 + NOT_PRODUCT(GCTraceTime tr("checkpointRootsFinalWork", PrintGCDetails, false, _gc_timer_cm);)
1.301
1.302 assert(haveFreelistLocks(), "must have free list locks");
1.303 assert_lock_strong(bitMapLock());
1.304 @@ -4966,11 +5044,11 @@
1.305 // the most recent young generation GC, minus those cleaned up by the
1.306 // concurrent precleaning.
1.307 if (CMSParallelRemarkEnabled && CollectedHeap::use_parallel_gc_threads()) {
1.308 - TraceTime t("Rescan (parallel) ", PrintGCDetails, false, gclog_or_tty);
1.309 + GCTraceTime t("Rescan (parallel) ", PrintGCDetails, false, _gc_timer_cm);
1.310 do_remark_parallel();
1.311 } else {
1.312 - TraceTime t("Rescan (non-parallel) ", PrintGCDetails, false,
1.313 - gclog_or_tty);
1.314 + GCTraceTime t("Rescan (non-parallel) ", PrintGCDetails, false,
1.315 + _gc_timer_cm);
1.316 do_remark_non_parallel();
1.317 }
1.318 }
1.319 @@ -4983,7 +5061,7 @@
1.320 verify_overflow_empty();
1.321
1.322 {
1.323 - NOT_PRODUCT(TraceTime ts("refProcessingWork", PrintGCDetails, false, gclog_or_tty);)
1.324 + NOT_PRODUCT(GCTraceTime ts("refProcessingWork", PrintGCDetails, false, _gc_timer_cm);)
1.325 refProcessingWork(asynch, clear_all_soft_refs);
1.326 }
1.327 verify_work_stacks_empty();
1.328 @@ -5044,6 +5122,8 @@
1.329 verify_after_remark();
1.330 }
1.331
1.332 + _gc_tracer_cm->report_object_count_after_gc(&_is_alive_closure);
1.333 +
1.334 // Change under the freelistLocks.
1.335 _collectorState = Sweeping;
1.336 // Call isAllClear() under bitMapLock
1.337 @@ -5697,7 +5777,7 @@
1.338 NULL, // space is set further below
1.339 &_markBitMap, &_markStack, &mrias_cl);
1.340 {
1.341 - TraceTime t("grey object rescan", PrintGCDetails, false, gclog_or_tty);
1.342 + GCTraceTime t("grey object rescan", PrintGCDetails, false, _gc_timer_cm);
1.343 // Iterate over the dirty cards, setting the corresponding bits in the
1.344 // mod union table.
1.345 {
1.346 @@ -5734,7 +5814,7 @@
1.347 Universe::verify();
1.348 }
1.349 {
1.350 - TraceTime t("root rescan", PrintGCDetails, false, gclog_or_tty);
1.351 + GCTraceTime t("root rescan", PrintGCDetails, false, _gc_timer_cm);
1.352
1.353 verify_work_stacks_empty();
1.354
1.355 @@ -5756,7 +5836,7 @@
1.356 }
1.357
1.358 {
1.359 - TraceTime t("visit unhandled CLDs", PrintGCDetails, false, gclog_or_tty);
1.360 + GCTraceTime t("visit unhandled CLDs", PrintGCDetails, false, _gc_timer_cm);
1.361
1.362 verify_work_stacks_empty();
1.363
1.364 @@ -5775,7 +5855,7 @@
1.365 }
1.366
1.367 {
1.368 - TraceTime t("dirty klass scan", PrintGCDetails, false, gclog_or_tty);
1.369 + GCTraceTime t("dirty klass scan", PrintGCDetails, false, _gc_timer_cm);
1.370
1.371 verify_work_stacks_empty();
1.372
1.373 @@ -5977,7 +6057,9 @@
1.374 _span, &_markBitMap, &_markStack,
1.375 &cmsKeepAliveClosure, false /* !preclean */);
1.376 {
1.377 - TraceTime t("weak refs processing", PrintGCDetails, false, gclog_or_tty);
1.378 + GCTraceTime t("weak refs processing", PrintGCDetails, false, _gc_timer_cm);
1.379 +
1.380 + ReferenceProcessorStats stats;
1.381 if (rp->processing_is_mt()) {
1.382 // Set the degree of MT here. If the discovery is done MT, there
1.383 // may have been a different number of threads doing the discovery
1.384 @@ -5996,16 +6078,20 @@
1.385 }
1.386 rp->set_active_mt_degree(active_workers);
1.387 CMSRefProcTaskExecutor task_executor(*this);
1.388 - rp->process_discovered_references(&_is_alive_closure,
1.389 + stats = rp->process_discovered_references(&_is_alive_closure,
1.390 &cmsKeepAliveClosure,
1.391 &cmsDrainMarkingStackClosure,
1.392 - &task_executor);
1.393 + &task_executor,
1.394 + _gc_timer_cm);
1.395 } else {
1.396 - rp->process_discovered_references(&_is_alive_closure,
1.397 + stats = rp->process_discovered_references(&_is_alive_closure,
1.398 &cmsKeepAliveClosure,
1.399 &cmsDrainMarkingStackClosure,
1.400 - NULL);
1.401 - }
1.402 + NULL,
1.403 + _gc_timer_cm);
1.404 + }
1.405 + _gc_tracer_cm->report_gc_reference_stats(stats);
1.406 +
1.407 }
1.408
1.409 // This is the point where the entire marking should have completed.
1.410 @@ -6013,7 +6099,7 @@
1.411
1.412 if (should_unload_classes()) {
1.413 {
1.414 - TraceTime t("class unloading", PrintGCDetails, false, gclog_or_tty);
1.415 + GCTraceTime t("class unloading", PrintGCDetails, false, _gc_timer_cm);
1.416
1.417 // Unload classes and purge the SystemDictionary.
1.418 bool purged_class = SystemDictionary::do_unloading(&_is_alive_closure);
1.419 @@ -6026,7 +6112,7 @@
1.420 }
1.421
1.422 {
1.423 - TraceTime t("scrub symbol table", PrintGCDetails, false, gclog_or_tty);
1.424 + GCTraceTime t("scrub symbol table", PrintGCDetails, false, _gc_timer_cm);
1.425 // Clean up unreferenced symbols in symbol table.
1.426 SymbolTable::unlink();
1.427 }
1.428 @@ -6035,7 +6121,7 @@
1.429 // CMS doesn't use the StringTable as hard roots when class unloading is turned off.
1.430 // Need to check if we really scanned the StringTable.
1.431 if ((roots_scanning_options() & SharedHeap::SO_Strings) == 0) {
1.432 - TraceTime t("scrub string table", PrintGCDetails, false, gclog_or_tty);
1.433 + GCTraceTime t("scrub string table", PrintGCDetails, false, _gc_timer_cm);
1.434 // Delete entries for dead interned strings.
1.435 StringTable::unlink(&_is_alive_closure);
1.436 }
1.437 @@ -6380,12 +6466,14 @@
1.438 _cmsGen->rotate_debug_collection_type();
1.439 }
1.440 )
1.441 +
1.442 + register_gc_end();
1.443 }
1.444
1.445 void CMSCollector::do_CMS_operation(CMS_op_type op, GCCause::Cause gc_cause) {
1.446 gclog_or_tty->date_stamp(PrintGC && PrintGCDateStamps);
1.447 TraceCPUTime tcpu(PrintGCDetails, true, gclog_or_tty);
1.448 - TraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, gclog_or_tty);
1.449 + GCTraceTime t(GCCauseString("GC", gc_cause), PrintGC, !PrintGCDetails, NULL);
1.450 TraceCollectorStats tcs(counters());
1.451
1.452 switch (op) {
