Mercurial > hg > graal-jvmci-8

comparison src/share/vm/runtime/safepoint.cpp @ 1291:4b0f2f4918ed

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
6933402: RFE: Improve PrintSafepointStatistics output to track cleanup time Summary: Improve the usability of safepoint statistics data. See bug evaluation for more details. Reviewed-by: ysr, dholmes
author xlu
date Wed, 10 Mar 2010 21:42:26 -0800
parents 528d98fe1037
children 0f6600cee529
comparison
equal deleted inserted replaced
1290:c8a467bf56ad 1291:4b0f2f4918ed
28 // -------------------------------------------------------------------------------------------------- 28 // --------------------------------------------------------------------------------------------------
29 // Implementation of Safepoint begin/end 29 // Implementation of Safepoint begin/end
30 30
31 SafepointSynchronize::SynchronizeState volatile SafepointSynchronize::_state = SafepointSynchronize::_not_synchronized; 31 SafepointSynchronize::SynchronizeState volatile SafepointSynchronize::_state = SafepointSynchronize::_not_synchronized;
32 volatile int SafepointSynchronize::_waiting_to_block = 0; 32 volatile int SafepointSynchronize::_waiting_to_block = 0;
33 jlong SafepointSynchronize::_last_safepoint = 0;
34 volatile int SafepointSynchronize::_safepoint_counter = 0; 33 volatile int SafepointSynchronize::_safepoint_counter = 0;
34 long SafepointSynchronize::_end_of_last_safepoint = 0;
35 static volatile int PageArmed = 0 ; // safepoint polling page is RO|RW vs PROT_NONE 35 static volatile int PageArmed = 0 ; // safepoint polling page is RO|RW vs PROT_NONE
36 static volatile int TryingToBlock = 0 ; // proximate value -- for advisory use only 36 static volatile int TryingToBlock = 0 ; // proximate value -- for advisory use only
37 static bool timeout_error_printed = false; 37 static bool timeout_error_printed = false;
38 38
39 // Roll all threads forward to a safepoint and suspend them all 39 // Roll all threads forward to a safepoint and suspend them all
40 void SafepointSynchronize::begin() { 40 void SafepointSynchronize::begin() {
41 41
42 Thread* myThread = Thread::current(); 42 Thread* myThread = Thread::current();
43 assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint"); 43 assert(myThread->is_VM_thread(), "Only VM thread may execute a safepoint");
44 44
45 _last_safepoint = os::javaTimeNanos(); 45 if (PrintSafepointStatistics || PrintSafepointStatisticsTimeout > 0) {
46 _safepoint_begin_time = os::javaTimeNanos();
47 _ts_of_current_safepoint = tty->time_stamp().seconds();
48 }
46 49
47 #ifndef SERIALGC 50 #ifndef SERIALGC
48 if (UseConcMarkSweepGC) { 51 if (UseConcMarkSweepGC) {
49 // In the future we should investigate whether CMS can use the 52 // In the future we should investigate whether CMS can use the
50 // more-general mechanism below. DLD (01/05). 53 // more-general mechanism below. DLD (01/05).
318 update_statistics_on_sync_end(os::javaTimeNanos()); 321 update_statistics_on_sync_end(os::javaTimeNanos());
319 } 322 }
320 323
321 // Call stuff that needs to be run when a safepoint is just about to be completed 324 // Call stuff that needs to be run when a safepoint is just about to be completed
322 do_cleanup_tasks(); 325 do_cleanup_tasks();
326
327 if (PrintSafepointStatistics) {
328 // Record how much time spend on the above cleanup tasks
329 update_statistics_on_cleanup_end(os::javaTimeNanos());
330 }
323 } 331 }
324 } 332 }
325 333
326 // Wake up all threads, so they are ready to resume execution after the safepoint 334 // Wake up all threads, so they are ready to resume execution after the safepoint
327 // operation has been carried out 335 // operation has been carried out
409 ConcurrentMarkSweepThread::desynchronize(false); 417 ConcurrentMarkSweepThread::desynchronize(false);
410 } else if (UseG1GC) { 418 } else if (UseG1GC) {
411 ConcurrentGCThread::safepoint_desynchronize(); 419 ConcurrentGCThread::safepoint_desynchronize();
412 } 420 }
413 #endif // SERIALGC 421 #endif // SERIALGC
422 // record this time so VMThread can keep track how much time has elasped
423 // since last safepoint.
424 _end_of_last_safepoint = os::javaTimeMillis();
414 } 425 }
415 426
416 bool SafepointSynchronize::is_cleanup_needed() { 427 bool SafepointSynchronize::is_cleanup_needed() {
417 // Need a safepoint if some inline cache buffers is non-empty 428 // Need a safepoint if some inline cache buffers is non-empty
418 if (!InlineCacheBuffer::is_empty()) return true; 429 if (!InlineCacheBuffer::is_empty()) return true;
443 } 454 }
444 } 455 }
445 456
446 // Various cleaning tasks that should be done periodically at safepoints 457 // Various cleaning tasks that should be done periodically at safepoints
447 void SafepointSynchronize::do_cleanup_tasks() { 458 void SafepointSynchronize::do_cleanup_tasks() {
448 jlong cleanup_time; 459 {
449 460 TraceTime t1("deflating idle monitors", TraceSafepoint);
450 // Update fat-monitor pool, since this is a safepoint. 461 ObjectSynchronizer::deflate_idle_monitors();
451 if (TraceSafepoint) { 462 }
452 cleanup_time = os::javaTimeNanos(); 463
453 } 464 {
454 465 TraceTime t2("updating inline caches", TraceSafepoint);
455 ObjectSynchronizer::deflate_idle_monitors(); 466 InlineCacheBuffer::update_inline_caches();
456 InlineCacheBuffer::update_inline_caches(); 467 }
468
457 if(UseCounterDecay && CounterDecay::is_decay_needed()) { 469 if(UseCounterDecay && CounterDecay::is_decay_needed()) {
470 TraceTime t3("decaying counter", TraceSafepoint);
458 CounterDecay::decay(); 471 CounterDecay::decay();
459 } 472 }
473
474 TraceTime t4("sweeping nmethods", TraceSafepoint);
460 NMethodSweeper::sweep(); 475 NMethodSweeper::sweep();
461
462 if (TraceSafepoint) {
463 tty->print_cr("do_cleanup_tasks takes "INT64_FORMAT_W(6) "ms",
464 (os::javaTimeNanos() - cleanup_time) / MICROUNITS);
465 }
466 } 476 }
467 477
468 478
469 bool SafepointSynchronize::safepoint_safe(JavaThread *thread, JavaThreadState state) { 479 bool SafepointSynchronize::safepoint_safe(JavaThread *thread, JavaThreadState state) {
470 switch(state) { 480 switch(state) {
977 987
978 // 988 //
979 // Statistics & Instrumentations 989 // Statistics & Instrumentations
980 // 990 //
981 SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL; 991 SafepointSynchronize::SafepointStats* SafepointSynchronize::_safepoint_stats = NULL;
992 jlong SafepointSynchronize::_safepoint_begin_time = 0;
982 int SafepointSynchronize::_cur_stat_index = 0; 993 int SafepointSynchronize::_cur_stat_index = 0;
983 julong SafepointSynchronize::_safepoint_reasons[VM_Operation::VMOp_Terminating]; 994 julong SafepointSynchronize::_safepoint_reasons[VM_Operation::VMOp_Terminating];
984 julong SafepointSynchronize::_coalesced_vmop_count = 0; 995 julong SafepointSynchronize::_coalesced_vmop_count = 0;
985 jlong SafepointSynchronize::_max_sync_time = 0; 996 jlong SafepointSynchronize::_max_sync_time = 0;
986 997 jlong SafepointSynchronize::_max_vmop_time = 0;
987 // last_safepoint_start_time records the start time of last safepoint. 998 float SafepointSynchronize::_ts_of_current_safepoint = 0.0f;
988 static jlong last_safepoint_start_time = 0; 999
989 static jlong sync_end_time = 0; 1000 static jlong cleanup_end_time = 0;
990 static bool need_to_track_page_armed_status = false; 1001 static bool need_to_track_page_armed_status = false;
991 static bool init_done = false; 1002 static bool init_done = false;
1003
1004 // Helper method to print the header.
1005 static void print_header() {
1006 tty->print(" vmop "
1007 "[threads: total initially_running wait_to_block] ");
1008 tty->print("[time: spin block sync cleanup vmop] ");
1009
1010 // no page armed status printed out if it is always armed.
1011 if (need_to_track_page_armed_status) {
1012 tty->print("page_armed ");
1013 }
1014
1015 tty->print_cr("page_trap_count");
1016 }
992 1017
993 void SafepointSynchronize::deferred_initialize_stat() { 1018 void SafepointSynchronize::deferred_initialize_stat() {
994 if (init_done) return; 1019 if (init_done) return;
995 1020
996 if (PrintSafepointStatisticsCount <= 0) { 1021 if (PrintSafepointStatisticsCount <= 0) {
1014 "not enough memory for safepoint instrumentation data"); 1039 "not enough memory for safepoint instrumentation data");
1015 1040
1016 if (UseCompilerSafepoints && DeferPollingPageLoopCount >= 0) { 1041 if (UseCompilerSafepoints && DeferPollingPageLoopCount >= 0) {
1017 need_to_track_page_armed_status = true; 1042 need_to_track_page_armed_status = true;
1018 } 1043 }
1019
1020 tty->print(" vmop_name "
1021 "[threads: total initially_running wait_to_block] ");
1022 tty->print("[time: spin block sync] "
1023 "[vmop_time time_elapsed] ");
1024
1025 // no page armed status printed out if it is always armed.
1026 if (need_to_track_page_armed_status) {
1027 tty->print("page_armed ");
1028 }
1029
1030 tty->print_cr("page_trap_count");
1031
1032 init_done = true; 1044 init_done = true;
1033 } 1045 }
1034 1046
1035 void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) { 1047 void SafepointSynchronize::begin_statistics(int nof_threads, int nof_running) {
1036 assert(init_done, "safepoint statistics array hasn't been initialized"); 1048 assert(init_done, "safepoint statistics array hasn't been initialized");
1037 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; 1049 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
1050
1051 spstat->_time_stamp = _ts_of_current_safepoint;
1038 1052
1039 VM_Operation *op = VMThread::vm_operation(); 1053 VM_Operation *op = VMThread::vm_operation();
1040 spstat->_vmop_type = (op != NULL ? op->type() : -1); 1054 spstat->_vmop_type = (op != NULL ? op->type() : -1);
1041 if (op != NULL) { 1055 if (op != NULL) {
1042 _safepoint_reasons[spstat->_vmop_type]++; 1056 _safepoint_reasons[spstat->_vmop_type]++;
1052 if (nof_running != 0) { 1066 if (nof_running != 0) {
1053 spstat->_time_to_spin = os::javaTimeNanos(); 1067 spstat->_time_to_spin = os::javaTimeNanos();
1054 } else { 1068 } else {
1055 spstat->_time_to_spin = 0; 1069 spstat->_time_to_spin = 0;
1056 } 1070 }
1057
1058 if (last_safepoint_start_time == 0) {
1059 spstat->_time_elapsed_since_last_safepoint = 0;
1060 } else {
1061 spstat->_time_elapsed_since_last_safepoint = _last_safepoint -
1062 last_safepoint_start_time;
1063 }
1064 last_safepoint_start_time = _last_safepoint;
1065 } 1071 }
1066 1072
1067 void SafepointSynchronize::update_statistics_on_spin_end() { 1073 void SafepointSynchronize::update_statistics_on_spin_end() {
1068 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; 1074 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
1069 1075
1095 } 1101 }
1096 1102
1097 // Records the end time of sync which will be used to calculate the total 1103 // Records the end time of sync which will be used to calculate the total
1098 // vm operation time. Again, the real time spending in syncing will be deducted 1104 // vm operation time. Again, the real time spending in syncing will be deducted
1099 // from the start of the sync time later when end_statistics is called. 1105 // from the start of the sync time later when end_statistics is called.
1100 spstat->_time_to_sync = end_time - _last_safepoint; 1106 spstat->_time_to_sync = end_time - _safepoint_begin_time;
1101 if (spstat->_time_to_sync > _max_sync_time) { 1107 if (spstat->_time_to_sync > _max_sync_time) {
1102 _max_sync_time = spstat->_time_to_sync; 1108 _max_sync_time = spstat->_time_to_sync;
1103 } 1109 }
1104 sync_end_time = end_time; 1110
1111 spstat->_time_to_do_cleanups = end_time;
1112 }
1113
1114 void SafepointSynchronize::update_statistics_on_cleanup_end(jlong end_time) {
1115 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
1116
1117 // Record how long spent in cleanup tasks.
1118 spstat->_time_to_do_cleanups = end_time - spstat->_time_to_do_cleanups;
1119
1120 cleanup_end_time = end_time;
1105 } 1121 }
1106 1122
1107 void SafepointSynchronize::end_statistics(jlong vmop_end_time) { 1123 void SafepointSynchronize::end_statistics(jlong vmop_end_time) {
1108 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index]; 1124 SafepointStats *spstat = &_safepoint_stats[_cur_stat_index];
1109 1125
1110 // Update the vm operation time. 1126 // Update the vm operation time.
1111 spstat->_time_to_exec_vmop = vmop_end_time - sync_end_time; 1127 spstat->_time_to_exec_vmop = vmop_end_time - cleanup_end_time;
1128 if (spstat->_time_to_exec_vmop > _max_vmop_time) {
1129 _max_vmop_time = spstat->_time_to_exec_vmop;
1130 }
1112 // Only the sync time longer than the specified 1131 // Only the sync time longer than the specified
1113 // PrintSafepointStatisticsTimeout will be printed out right away. 1132 // PrintSafepointStatisticsTimeout will be printed out right away.
1114 // By default, it is -1 meaning all samples will be put into the list. 1133 // By default, it is -1 meaning all samples will be put into the list.
1115 if ( PrintSafepointStatisticsTimeout > 0) { 1134 if ( PrintSafepointStatisticsTimeout > 0) {
1116 if (spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) { 1135 if (spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) {
1117 print_statistics(); 1136 print_statistics();
1118 } 1137 }
1119 } else { 1138 } else {
1120 // The safepoint statistics will be printed out when the _safepoin_stats 1139 // The safepoint statistics will be printed out when the _safepoin_stats
1121 // array fills up. 1140 // array fills up.
1122 if (_cur_stat_index != PrintSafepointStatisticsCount - 1) { 1141 if (_cur_stat_index == PrintSafepointStatisticsCount - 1) {
1123 _cur_stat_index ++;
1124 } else {
1125 print_statistics(); 1142 print_statistics();
1126 _cur_stat_index = 0; 1143 _cur_stat_index = 0;
1127 tty->print_cr(""); 1144 } else {
1145 _cur_stat_index++;
1128 } 1146 }
1129 } 1147 }
1130 } 1148 }
1131 1149
1132 void SafepointSynchronize::print_statistics() { 1150 void SafepointSynchronize::print_statistics() {
1133 int index;
1134 SafepointStats* sstats = _safepoint_stats; 1151 SafepointStats* sstats = _safepoint_stats;
1135 1152
1136 for (index = 0; index <= _cur_stat_index; index++) { 1153 for (int index = 0; index <= _cur_stat_index; index++) {
1154 if (index % 30 == 0) {
1155 print_header();
1156 }
1137 sstats = &_safepoint_stats[index]; 1157 sstats = &_safepoint_stats[index];
1138 tty->print("%-28s [" 1158 tty->print("%.3f: ", sstats->_time_stamp);
1159 tty->print("%-26s ["
1139 INT32_FORMAT_W(8)INT32_FORMAT_W(11)INT32_FORMAT_W(15) 1160 INT32_FORMAT_W(8)INT32_FORMAT_W(11)INT32_FORMAT_W(15)
1140 "] ", 1161 " ] ",
1141 sstats->_vmop_type == -1 ? "no vm operation" : 1162 sstats->_vmop_type == -1 ? "no vm operation" :
1142 VM_Operation::name(sstats->_vmop_type), 1163 VM_Operation::name(sstats->_vmop_type),
1143 sstats->_nof_total_threads, 1164 sstats->_nof_total_threads,
1144 sstats->_nof_initial_running_threads, 1165 sstats->_nof_initial_running_threads,
1145 sstats->_nof_threads_wait_to_block); 1166 sstats->_nof_threads_wait_to_block);
1146 // "/ MICROUNITS " is to convert the unit from nanos to millis. 1167 // "/ MICROUNITS " is to convert the unit from nanos to millis.
1147 tty->print(" [" 1168 tty->print(" ["
1148 INT64_FORMAT_W(6)INT64_FORMAT_W(6)INT64_FORMAT_W(6) 1169 INT64_FORMAT_W(6)INT64_FORMAT_W(6)
1149 "] " 1170 INT64_FORMAT_W(6)INT64_FORMAT_W(6)
1150 "["INT64_FORMAT_W(6)INT64_FORMAT_W(9) "] ", 1171 INT64_FORMAT_W(6)" ] ",
1151 sstats->_time_to_spin / MICROUNITS, 1172 sstats->_time_to_spin / MICROUNITS,
1152 sstats->_time_to_wait_to_block / MICROUNITS, 1173 sstats->_time_to_wait_to_block / MICROUNITS,
1153 sstats->_time_to_sync / MICROUNITS, 1174 sstats->_time_to_sync / MICROUNITS,
1154 sstats->_time_to_exec_vmop / MICROUNITS, 1175 sstats->_time_to_do_cleanups / MICROUNITS,
1155 sstats->_time_elapsed_since_last_safepoint / MICROUNITS); 1176 sstats->_time_to_exec_vmop / MICROUNITS);
1156 1177
1157 if (need_to_track_page_armed_status) { 1178 if (need_to_track_page_armed_status) {
1158 tty->print(INT32_FORMAT" ", sstats->_page_armed); 1179 tty->print(INT32_FORMAT" ", sstats->_page_armed);
1159 } 1180 }
1160 tty->print_cr(INT32_FORMAT" ", sstats->_nof_threads_hit_page_trap); 1181 tty->print_cr(INT32_FORMAT" ", sstats->_nof_threads_hit_page_trap);
1172 // During VM exit, end_statistics may not get called and in that 1193 // During VM exit, end_statistics may not get called and in that
1173 // case, if the sync time is less than PrintSafepointStatisticsTimeout, 1194 // case, if the sync time is less than PrintSafepointStatisticsTimeout,
1174 // don't print it out. 1195 // don't print it out.
1175 // Approximate the vm op time. 1196 // Approximate the vm op time.
1176 _safepoint_stats[_cur_stat_index]._time_to_exec_vmop = 1197 _safepoint_stats[_cur_stat_index]._time_to_exec_vmop =
1177 os::javaTimeNanos() - sync_end_time; 1198 os::javaTimeNanos() - cleanup_end_time;
1178 1199
1179 if ( PrintSafepointStatisticsTimeout < 0 || 1200 if ( PrintSafepointStatisticsTimeout < 0 ||
1180 spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) { 1201 spstat->_time_to_sync > PrintSafepointStatisticsTimeout * MICROUNITS) {
1181 print_statistics(); 1202 print_statistics();
1182 } 1203 }
1201 1222
1202 tty->print_cr(UINT64_FORMAT_W(5)" VM operations coalesced during safepoint", 1223 tty->print_cr(UINT64_FORMAT_W(5)" VM operations coalesced during safepoint",
1203 _coalesced_vmop_count); 1224 _coalesced_vmop_count);
1204 tty->print_cr("Maximum sync time "INT64_FORMAT_W(5)" ms", 1225 tty->print_cr("Maximum sync time "INT64_FORMAT_W(5)" ms",
1205 _max_sync_time / MICROUNITS); 1226 _max_sync_time / MICROUNITS);
1227 tty->print_cr("Maximum vm operation time (except for Exit VM operation) "
1228 INT64_FORMAT_W(5)" ms",
1229 _max_vmop_time / MICROUNITS);
1206 } 1230 }
1207 1231
1208 // ------------------------------------------------------------------------------------------------ 1232 // ------------------------------------------------------------------------------------------------
1209 // Non-product code 1233 // Non-product code
1210 1234