comparison src/share/vm/gc_implementation/g1/concurrentMarkThread.cpp @ 6007:5c86f8211d1e

7160728: Introduce an extra logging level for G1 logging Summary: Added log levels "fine", "finer" and "finest". Let PrintGC map to "fine" and PrintGCDetails map to "finer". Separated out the per worker information in the G1 logging to the "finest" level. Reviewed-by: stefank, jwilhelm, tonyp, johnc
author brutisso
date Fri, 13 Apr 2012 01:59:38 +0200
parents 64bf7c8270cb
children 37552638d24a
comparison
equal deleted inserted replaced
5994:4a32c51458b9 6007:5c86f8211d1e
24 24
25 #include "precompiled.hpp" 25 #include "precompiled.hpp"
26 #include "gc_implementation/g1/concurrentMarkThread.inline.hpp" 26 #include "gc_implementation/g1/concurrentMarkThread.inline.hpp"
27 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" 27 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
28 #include "gc_implementation/g1/g1CollectorPolicy.hpp" 28 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
29 #include "gc_implementation/g1/g1Log.hpp"
29 #include "gc_implementation/g1/g1MMUTracker.hpp" 30 #include "gc_implementation/g1/g1MMUTracker.hpp"
30 #include "gc_implementation/g1/vm_operations_g1.hpp" 31 #include "gc_implementation/g1/vm_operations_g1.hpp"
31 #include "memory/resourceArea.hpp" 32 #include "memory/resourceArea.hpp"
32 #include "runtime/vmThread.hpp" 33 #include "runtime/vmThread.hpp"
33 34
102 // without the root regions have been scanned which would be a 103 // without the root regions have been scanned which would be a
103 // correctness issue. 104 // correctness issue.
104 105
105 double scan_start = os::elapsedTime(); 106 double scan_start = os::elapsedTime();
106 if (!cm()->has_aborted()) { 107 if (!cm()->has_aborted()) {
107 if (PrintGC) { 108 if (G1Log::fine()) {
108 gclog_or_tty->date_stamp(PrintGCDateStamps); 109 gclog_or_tty->date_stamp(PrintGCDateStamps);
109 gclog_or_tty->stamp(PrintGCTimeStamps); 110 gclog_or_tty->stamp(PrintGCTimeStamps);
110 gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]"); 111 gclog_or_tty->print_cr("[GC concurrent-root-region-scan-start]");
111 } 112 }
112 113
113 _cm->scanRootRegions(); 114 _cm->scanRootRegions();
114 115
115 double scan_end = os::elapsedTime(); 116 double scan_end = os::elapsedTime();
116 if (PrintGC) { 117 if (G1Log::fine()) {
117 gclog_or_tty->date_stamp(PrintGCDateStamps); 118 gclog_or_tty->date_stamp(PrintGCDateStamps);
118 gclog_or_tty->stamp(PrintGCTimeStamps); 119 gclog_or_tty->stamp(PrintGCTimeStamps);
119 gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf]", 120 gclog_or_tty->print_cr("[GC concurrent-root-region-scan-end, %1.7lf]",
120 scan_end - scan_start); 121 scan_end - scan_start);
121 } 122 }
122 } 123 }
123 124
124 double mark_start_sec = os::elapsedTime(); 125 double mark_start_sec = os::elapsedTime();
125 if (PrintGC) { 126 if (G1Log::fine()) {
126 gclog_or_tty->date_stamp(PrintGCDateStamps); 127 gclog_or_tty->date_stamp(PrintGCDateStamps);
127 gclog_or_tty->stamp(PrintGCTimeStamps); 128 gclog_or_tty->stamp(PrintGCTimeStamps);
128 gclog_or_tty->print_cr("[GC concurrent-mark-start]"); 129 gclog_or_tty->print_cr("[GC concurrent-mark-start]");
129 } 130 }
130 131
144 double remark_prediction_ms = g1_policy->predict_remark_time_ms(); 145 double remark_prediction_ms = g1_policy->predict_remark_time_ms();
145 jlong sleep_time_ms = mmu_tracker->when_ms(now, remark_prediction_ms); 146 jlong sleep_time_ms = mmu_tracker->when_ms(now, remark_prediction_ms);
146 os::sleep(current_thread, sleep_time_ms, false); 147 os::sleep(current_thread, sleep_time_ms, false);
147 } 148 }
148 149
149 if (PrintGC) { 150 if (G1Log::fine()) {
150 gclog_or_tty->date_stamp(PrintGCDateStamps); 151 gclog_or_tty->date_stamp(PrintGCDateStamps);
151 gclog_or_tty->stamp(PrintGCTimeStamps); 152 gclog_or_tty->stamp(PrintGCTimeStamps);
152 gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf sec]", 153 gclog_or_tty->print_cr("[GC concurrent-mark-end, %1.7lf sec]",
153 mark_end_sec - mark_start_sec); 154 mark_end_sec - mark_start_sec);
154 } 155 }
163 gclog_or_tty->print_cr("Restarting conc marking because of MS overflow " 164 gclog_or_tty->print_cr("Restarting conc marking because of MS overflow "
164 "in remark (restart #%d).", iter); 165 "in remark (restart #%d).", iter);
165 } 166 }
166 167
167 if (cm()->restart_for_overflow()) { 168 if (cm()->restart_for_overflow()) {
168 if (PrintGC) { 169 if (G1Log::fine()) {
169 gclog_or_tty->date_stamp(PrintGCDateStamps); 170 gclog_or_tty->date_stamp(PrintGCDateStamps);
170 gclog_or_tty->stamp(PrintGCTimeStamps); 171 gclog_or_tty->stamp(PrintGCTimeStamps);
171 gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]"); 172 gclog_or_tty->print_cr("[GC concurrent-mark-restart-for-overflow]");
172 } 173 }
173 } 174 }
209 // case they are needed by the pause. If a Full GC takes 210 // case they are needed by the pause. If a Full GC takes
210 // place, it would wait for us to process the regions 211 // place, it would wait for us to process the regions
211 // reclaimed by cleanup. 212 // reclaimed by cleanup.
212 213
213 double cleanup_start_sec = os::elapsedTime(); 214 double cleanup_start_sec = os::elapsedTime();
214 if (PrintGC) { 215 if (G1Log::fine()) {
215 gclog_or_tty->date_stamp(PrintGCDateStamps); 216 gclog_or_tty->date_stamp(PrintGCDateStamps);
216 gclog_or_tty->stamp(PrintGCTimeStamps); 217 gclog_or_tty->stamp(PrintGCTimeStamps);
217 gclog_or_tty->print_cr("[GC concurrent-cleanup-start]"); 218 gclog_or_tty->print_cr("[GC concurrent-cleanup-start]");
218 } 219 }
219 220
230 // while it's trying to join the STS, which is conditional on 231 // while it's trying to join the STS, which is conditional on
231 // the GC workers finishing. 232 // the GC workers finishing.
232 g1h->reset_free_regions_coming(); 233 g1h->reset_free_regions_coming();
233 234
234 double cleanup_end_sec = os::elapsedTime(); 235 double cleanup_end_sec = os::elapsedTime();
235 if (PrintGC) { 236 if (G1Log::fine()) {
236 gclog_or_tty->date_stamp(PrintGCDateStamps); 237 gclog_or_tty->date_stamp(PrintGCDateStamps);
237 gclog_or_tty->stamp(PrintGCTimeStamps); 238 gclog_or_tty->stamp(PrintGCTimeStamps);
238 gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf]", 239 gclog_or_tty->print_cr("[GC concurrent-cleanup-end, %1.7lf]",
239 cleanup_end_sec - cleanup_start_sec); 240 cleanup_end_sec - cleanup_start_sec);
240 } 241 }
271 g1_policy->record_concurrent_mark_cleanup_completed(); 272 g1_policy->record_concurrent_mark_cleanup_completed();
272 } 273 }
273 _sts.leave(); 274 _sts.leave();
274 275
275 if (cm()->has_aborted()) { 276 if (cm()->has_aborted()) {
276 if (PrintGC) { 277 if (G1Log::fine()) {
277 gclog_or_tty->date_stamp(PrintGCDateStamps); 278 gclog_or_tty->date_stamp(PrintGCDateStamps);
278 gclog_or_tty->stamp(PrintGCTimeStamps); 279 gclog_or_tty->stamp(PrintGCTimeStamps);
279 gclog_or_tty->print_cr("[GC concurrent-mark-abort]"); 280 gclog_or_tty->print_cr("[GC concurrent-mark-abort]");
280 } 281 }
281 } 282 }