31 #include "gc_implementation/g1/g1AllocRegion.inline.hpp" |
31 #include "gc_implementation/g1/g1AllocRegion.inline.hpp" |
32 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" |
32 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" |
33 #include "gc_implementation/g1/g1CollectorPolicy.hpp" |
33 #include "gc_implementation/g1/g1CollectorPolicy.hpp" |
34 #include "gc_implementation/g1/g1ErgoVerbose.hpp" |
34 #include "gc_implementation/g1/g1ErgoVerbose.hpp" |
35 #include "gc_implementation/g1/g1EvacFailure.hpp" |
35 #include "gc_implementation/g1/g1EvacFailure.hpp" |
|
36 #include "gc_implementation/g1/g1GCPhaseTimes.hpp" |
36 #include "gc_implementation/g1/g1Log.hpp" |
37 #include "gc_implementation/g1/g1Log.hpp" |
37 #include "gc_implementation/g1/g1MarkSweep.hpp" |
38 #include "gc_implementation/g1/g1MarkSweep.hpp" |
38 #include "gc_implementation/g1/g1OopClosures.inline.hpp" |
39 #include "gc_implementation/g1/g1OopClosures.inline.hpp" |
39 #include "gc_implementation/g1/g1RemSet.inline.hpp" |
40 #include "gc_implementation/g1/g1RemSet.inline.hpp" |
40 #include "gc_implementation/g1/heapRegion.inline.hpp" |
41 #include "gc_implementation/g1/heapRegion.inline.hpp" |
2272 DirtyCardQueueSet& dcqs = JavaThread::dirty_card_queue_set(); |
2273 DirtyCardQueueSet& dcqs = JavaThread::dirty_card_queue_set(); |
2273 int n_completed_buffers = 0; |
2274 int n_completed_buffers = 0; |
2274 while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { |
2275 while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { |
2275 n_completed_buffers++; |
2276 n_completed_buffers++; |
2276 } |
2277 } |
2277 g1_policy()->record_update_rs_processed_buffers(worker_i, |
2278 g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, |
2278 (double) n_completed_buffers); |
2279 (double) n_completed_buffers); |
2279 dcqs.clear_n_completed_buffers(); |
2280 dcqs.clear_n_completed_buffers(); |
2280 assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); |
2281 assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); |
2281 } |
2282 } |
2282 |
2283 |
3631 // in the collector policy code, so let's not print this as the output |
3632 // in the collector policy code, so let's not print this as the output |
3632 // is messy if we do. |
3633 // is messy if we do. |
3633 gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); |
3634 gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); |
3634 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); |
3635 TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); |
3635 |
3636 |
3636 GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) |
3637 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? |
3637 .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") |
3638 workers()->active_workers() : 1); |
3638 .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); |
3639 g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers, |
3639 TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); |
3640 g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause()); |
3640 |
3641 |
3641 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); |
3642 TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); |
3642 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); |
3643 TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); |
3643 |
3644 |
3644 // If the secondary_free_list is not empty, append it to the |
3645 // If the secondary_free_list is not empty, append it to the |
3697 // We should call this after we retire the mutator alloc |
3698 // We should call this after we retire the mutator alloc |
3698 // region(s) so that all the ALLOC / RETIRE events are generated |
3699 // region(s) so that all the ALLOC / RETIRE events are generated |
3699 // before the start GC event. |
3700 // before the start GC event. |
3700 _hr_printer.start_gc(false /* full */, (size_t) total_collections()); |
3701 _hr_printer.start_gc(false /* full */, (size_t) total_collections()); |
3701 |
3702 |
|
3703 // This timing is only used by the ergonomics to handle our pause target. |
|
3704 // It is unclear why this should not include the full pause. We will |
|
3705 // investigate this in CR 7178365. |
|
3706 // |
|
3707 // Preserving the old comment here if that helps the investigation: |
|
3708 // |
3702 // The elapsed time induced by the start time below deliberately elides |
3709 // The elapsed time induced by the start time below deliberately elides |
3703 // the possible verification above. |
3710 // the possible verification above. |
3704 double start_time_sec = os::elapsedTime(); |
3711 double sample_start_time_sec = os::elapsedTime(); |
3705 size_t start_used_bytes = used(); |
3712 size_t start_used_bytes = used(); |
3706 |
3713 |
3707 #if YOUNG_LIST_VERBOSE |
3714 #if YOUNG_LIST_VERBOSE |
3708 gclog_or_tty->print_cr("\nBefore recording pause start.\nYoung_list:"); |
3715 gclog_or_tty->print_cr("\nBefore recording pause start.\nYoung_list:"); |
3709 _young_list->print(); |
3716 _young_list->print(); |
3710 g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty); |
3717 g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty); |
3711 #endif // YOUNG_LIST_VERBOSE |
3718 #endif // YOUNG_LIST_VERBOSE |
3712 |
3719 |
3713 g1_policy()->record_collection_pause_start(start_time_sec, |
3720 g1_policy()->record_collection_pause_start(sample_start_time_sec, |
3714 start_used_bytes); |
3721 start_used_bytes); |
3715 |
3722 |
3716 double scan_wait_start = os::elapsedTime(); |
3723 double scan_wait_start = os::elapsedTime(); |
3717 // We have to wait until the CM threads finish scanning the |
3724 // We have to wait until the CM threads finish scanning the |
3718 // root regions as it's the only way to ensure that all the |
3725 // root regions as it's the only way to ensure that all the |
3719 // objects on them have been correctly scanned before we start |
3726 // objects on them have been correctly scanned before we start |
3720 // moving them during the GC. |
3727 // moving them during the GC. |
3721 bool waited = _cm->root_regions()->wait_until_scan_finished(); |
3728 bool waited = _cm->root_regions()->wait_until_scan_finished(); |
|
3729 double wait_time_ms = 0.0; |
3722 if (waited) { |
3730 if (waited) { |
3723 double scan_wait_end = os::elapsedTime(); |
3731 double scan_wait_end = os::elapsedTime(); |
3724 double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; |
3732 wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; |
3725 g1_policy()->record_root_region_scan_wait_time(wait_time_ms); |
|
3726 } |
3733 } |
|
3734 g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms); |
3727 |
3735 |
3728 #if YOUNG_LIST_VERBOSE |
3736 #if YOUNG_LIST_VERBOSE |
3729 gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:"); |
3737 gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:"); |
3730 _young_list->print(); |
3738 _young_list->print(); |
3731 #endif // YOUNG_LIST_VERBOSE |
3739 #endif // YOUNG_LIST_VERBOSE |
3875 true /* verify_enqueued_buffers */, |
3883 true /* verify_enqueued_buffers */, |
3876 true /* verify_thread_buffers */, |
3884 true /* verify_thread_buffers */, |
3877 true /* verify_fingers */); |
3885 true /* verify_fingers */); |
3878 _cm->note_end_of_gc(); |
3886 _cm->note_end_of_gc(); |
3879 |
3887 |
3880 double end_time_sec = os::elapsedTime(); |
3888 // Collect thread local data to allow the ergonomics to use |
3881 double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; |
3889 // the collected information |
3882 g1_policy()->record_pause_time_ms(pause_time_ms); |
3890 g1_policy()->phase_times()->collapse_par_times(); |
3883 int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? |
3891 |
3884 workers()->active_workers() : 1); |
3892 // This timing is only used by the ergonomics to handle our pause target. |
3885 g1_policy()->record_collection_pause_end(active_workers); |
3893 // It is unclear why this should not include the full pause. We will |
|
3894 // investigate this in CR 7178365. |
|
3895 double sample_end_time_sec = os::elapsedTime(); |
|
3896 double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS; |
|
3897 g1_policy()->record_collection_pause_end(pause_time_ms); |
3886 |
3898 |
3887 MemoryService::track_memory_usage(); |
3899 MemoryService::track_memory_usage(); |
3888 |
3900 |
3889 // In prepare_for_verify() below we'll need to scan the deferred |
3901 // In prepare_for_verify() below we'll need to scan the deferred |
3890 // update buffers to bring the RSets up-to-date if |
3902 // update buffers to bring the RSets up-to-date if |
3927 // that all the COMMIT events are generated before the end GC |
3939 // that all the COMMIT events are generated before the end GC |
3928 // event, and after we retire the GC alloc regions so that all |
3940 // event, and after we retire the GC alloc regions so that all |
3929 // RETIRE events are generated before the end GC event. |
3941 // RETIRE events are generated before the end GC event. |
3930 _hr_printer.end_gc(false /* full */, (size_t) total_collections()); |
3942 _hr_printer.end_gc(false /* full */, (size_t) total_collections()); |
3931 |
3943 |
3932 // We have to do this after we decide whether to expand the heap or not. |
|
3933 g1_policy()->print_heap_transition(); |
|
3934 |
|
3935 if (mark_in_progress()) { |
3944 if (mark_in_progress()) { |
3936 concurrent_mark()->update_g1_committed(); |
3945 concurrent_mark()->update_g1_committed(); |
3937 } |
3946 } |
3938 |
3947 |
3939 #ifdef TRACESPINNING |
3948 #ifdef TRACESPINNING |
3940 ParallelTaskTerminator::print_termination_counts(); |
3949 ParallelTaskTerminator::print_termination_counts(); |
3941 #endif |
3950 #endif |
3942 |
3951 |
3943 gc_epilogue(false); |
3952 gc_epilogue(false); |
3944 } |
3953 |
3945 |
3954 g1_policy()->phase_times()->note_gc_end(os::elapsedTime()); |
3946 // The closing of the inner scope, immediately above, will complete |
3955 |
3947 // logging at the "fine" level. The record_collection_pause_end() call |
3956 // We have to do this after we decide whether to expand the heap or not. |
3948 // above will complete logging at the "finer" level. |
3957 g1_policy()->print_heap_transition(); |
3949 // |
3958 } |
3950 // It is not yet to safe, however, to tell the concurrent mark to |
3959 |
|
3960 // It is not yet to safe to tell the concurrent mark to |
3951 // start as we have some optional output below. We don't want the |
3961 // start as we have some optional output below. We don't want the |
3952 // output from the concurrent mark thread interfering with this |
3962 // output from the concurrent mark thread interfering with this |
3953 // logging output either. |
3963 // logging output either. |
3954 |
3964 |
3955 _hrs.verify_optional(); |
3965 _hrs.verify_optional(); |
4742 double start = os::elapsedTime(); |
4752 double start = os::elapsedTime(); |
4743 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator); |
4753 G1ParEvacuateFollowersClosure evac(_g1h, &pss, _queues, &_terminator); |
4744 evac.do_void(); |
4754 evac.do_void(); |
4745 double elapsed_ms = (os::elapsedTime()-start)*1000.0; |
4755 double elapsed_ms = (os::elapsedTime()-start)*1000.0; |
4746 double term_ms = pss.term_time()*1000.0; |
4756 double term_ms = pss.term_time()*1000.0; |
4747 _g1h->g1_policy()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); |
4757 _g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); |
4748 _g1h->g1_policy()->record_termination(worker_id, term_ms, pss.term_attempts()); |
4758 _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts()); |
4749 } |
4759 } |
4750 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); |
4760 _g1h->g1_policy()->record_thread_age_table(pss.age_table()); |
4751 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); |
4761 _g1h->update_surviving_young_words(pss.surviving_young_words()+1); |
4752 |
4762 |
4753 if (ParallelGCVerbose) { |
4763 if (ParallelGCVerbose) { |
4872 buf_scan_non_heap_roots.done(); |
4882 buf_scan_non_heap_roots.done(); |
4873 buf_scan_perm.done(); |
4883 buf_scan_perm.done(); |
4874 |
4884 |
4875 double ext_roots_end = os::elapsedTime(); |
4885 double ext_roots_end = os::elapsedTime(); |
4876 |
4886 |
4877 g1_policy()->reset_obj_copy_time(worker_i); |
4887 g1_policy()->phase_times()->reset_obj_copy_time(worker_i); |
4878 double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() + |
4888 double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() + |
4879 buf_scan_non_heap_roots.closure_app_seconds(); |
4889 buf_scan_non_heap_roots.closure_app_seconds(); |
4880 g1_policy()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); |
4890 g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); |
4881 |
4891 |
4882 double ext_root_time_ms = |
4892 double ext_root_time_ms = |
4883 ((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0; |
4893 ((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0; |
4884 |
4894 |
4885 g1_policy()->record_ext_root_scan_time(worker_i, ext_root_time_ms); |
4895 g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms); |
4886 |
4896 |
4887 // During conc marking we have to filter the per-thread SATB buffers |
4897 // During conc marking we have to filter the per-thread SATB buffers |
4888 // to make sure we remove any oops into the CSet (which will show up |
4898 // to make sure we remove any oops into the CSet (which will show up |
4889 // as implicitly live). |
4899 // as implicitly live). |
4890 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { |
4900 if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { |
4891 if (mark_in_progress()) { |
4901 if (mark_in_progress()) { |
4892 JavaThread::satb_mark_queue_set().filter_thread_buffers(); |
4902 JavaThread::satb_mark_queue_set().filter_thread_buffers(); |
4893 } |
4903 } |
4894 } |
4904 } |
4895 double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0; |
4905 double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0; |
4896 g1_policy()->record_satb_filtering_time(worker_i, satb_filtering_ms); |
4906 g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms); |
4897 |
4907 |
4898 // Now scan the complement of the collection set. |
4908 // Now scan the complement of the collection set. |
4899 if (scan_rs != NULL) { |
4909 if (scan_rs != NULL) { |
4900 g1_rem_set()->oops_into_collection_set_do(scan_rs, worker_i); |
4910 g1_rem_set()->oops_into_collection_set_do(scan_rs, worker_i); |
4901 } |
4911 } |
5391 // retire any active alloc buffers |
5401 // retire any active alloc buffers |
5392 pss.retire_alloc_buffers(); |
5402 pss.retire_alloc_buffers(); |
5393 assert(pss.refs()->is_empty(), "both queue and overflow should be empty"); |
5403 assert(pss.refs()->is_empty(), "both queue and overflow should be empty"); |
5394 |
5404 |
5395 double ref_proc_time = os::elapsedTime() - ref_proc_start; |
5405 double ref_proc_time = os::elapsedTime() - ref_proc_start; |
5396 g1_policy()->record_ref_proc_time(ref_proc_time * 1000.0); |
5406 g1_policy()->phase_times()->record_ref_proc_time(ref_proc_time * 1000.0); |
5397 } |
5407 } |
5398 |
5408 |
5399 // Weak Reference processing during an evacuation pause (part 2). |
5409 // Weak Reference processing during an evacuation pause (part 2). |
5400 void G1CollectedHeap::enqueue_discovered_references() { |
5410 void G1CollectedHeap::enqueue_discovered_references() { |
5401 double ref_enq_start = os::elapsedTime(); |
5411 double ref_enq_start = os::elapsedTime(); |
5428 // CM's reference processing also cleans up the string and symbol tables. |
5438 // CM's reference processing also cleans up the string and symbol tables. |
5429 // Should we do that here also? We could, but it is a serial operation |
5439 // Should we do that here also? We could, but it is a serial operation |
5430 // and could signicantly increase the pause time. |
5440 // and could signicantly increase the pause time. |
5431 |
5441 |
5432 double ref_enq_time = os::elapsedTime() - ref_enq_start; |
5442 double ref_enq_time = os::elapsedTime() - ref_enq_start; |
5433 g1_policy()->record_ref_enq_time(ref_enq_time * 1000.0); |
5443 g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0); |
5434 } |
5444 } |
5435 |
5445 |
5436 void G1CollectedHeap::evacuate_collection_set() { |
5446 void G1CollectedHeap::evacuate_collection_set() { |
5437 _expand_heap_after_alloc_failure = true; |
5447 _expand_heap_after_alloc_failure = true; |
5438 set_evacuation_failed(false); |
5448 set_evacuation_failed(false); |
5491 // taken for the SRS destructor is NOT included in the |
5501 // taken for the SRS destructor is NOT included in the |
5492 // reported parallel time. |
5502 // reported parallel time. |
5493 } |
5503 } |
5494 |
5504 |
5495 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; |
5505 double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; |
5496 g1_policy()->record_par_time(par_time_ms); |
5506 g1_policy()->phase_times()->record_par_time(par_time_ms); |
5497 |
5507 |
5498 double code_root_fixup_time_ms = |
5508 double code_root_fixup_time_ms = |
5499 (os::elapsedTime() - end_par_time_sec) * 1000.0; |
5509 (os::elapsedTime() - end_par_time_sec) * 1000.0; |
5500 g1_policy()->record_code_root_fixup_time(code_root_fixup_time_ms); |
5510 g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms); |
5501 |
5511 |
5502 set_par_threads(0); |
5512 set_par_threads(0); |
5503 |
5513 |
5504 // Process any discovered reference objects - we have |
5514 // Process any discovered reference objects - we have |
5505 // to do this _before_ we retire the GC alloc regions |
5515 // to do this _before_ we retire the GC alloc regions |
5866 |
5876 |
5867 update_sets_after_freeing_regions(pre_used, &local_free_list, |
5877 update_sets_after_freeing_regions(pre_used, &local_free_list, |
5868 NULL /* old_proxy_set */, |
5878 NULL /* old_proxy_set */, |
5869 NULL /* humongous_proxy_set */, |
5879 NULL /* humongous_proxy_set */, |
5870 false /* par */); |
5880 false /* par */); |
5871 policy->record_young_free_cset_time_ms(young_time_ms); |
5881 policy->phase_times()->record_young_free_cset_time_ms(young_time_ms); |
5872 policy->record_non_young_free_cset_time_ms(non_young_time_ms); |
5882 policy->phase_times()->record_non_young_free_cset_time_ms(non_young_time_ms); |
5873 } |
5883 } |
5874 |
5884 |
5875 // This routine is similar to the above but does not record |
5885 // This routine is similar to the above but does not record |
5876 // any policy statistics or update free lists; we are abandoning |
5886 // any policy statistics or update free lists; we are abandoning |
5877 // the current incremental collection set in preparation of a |
5887 // the current incremental collection set in preparation of a |