changeset 5772:6aa49042b101

8025277: Add -XX: flag to print code cache sweeper statistics Summary: New diagnostic flag prints statistics about the code cache sweeper Reviewed-by: kvn Contributed-by: tobi.hartmann@gmail.com
author anoll
date Thu, 19 Dec 2013 14:08:02 +0100
parents d6e7180abab5
children 5a83a5546dc7
files src/share/vm/runtime/globals.hpp src/share/vm/runtime/java.cpp src/share/vm/runtime/sweeper.cpp src/share/vm/runtime/sweeper.hpp
diffstat 4 files changed, 66 insertions(+), 31 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/vm/runtime/globals.hpp	Thu Dec 19 06:09:16 2013 +0100
+++ b/src/share/vm/runtime/globals.hpp	Thu Dec 19 14:08:02 2013 +0100
@@ -2531,6 +2531,9 @@
   develop(bool, PrintMethodFlushing, false,                                 \
           "Print the nmethods being flushed")                               \
                                                                             \
+  diagnostic(bool, PrintMethodFlushingStatistics, false,                    \
+          "print statistics about method flushing")                         \
+                                                                            \
   develop(bool, UseRelocIndex, false,                                       \
           "Use an index to speed random access to relocations")             \
                                                                             \
--- a/src/share/vm/runtime/java.cpp	Thu Dec 19 06:09:16 2013 +0100
+++ b/src/share/vm/runtime/java.cpp	Thu Dec 19 14:08:02 2013 +0100
@@ -52,6 +52,7 @@
 #include "runtime/memprofiler.hpp"
 #include "runtime/sharedRuntime.hpp"
 #include "runtime/statSampler.hpp"
+#include "runtime/sweeper.hpp"
 #include "runtime/task.hpp"
 #include "runtime/thread.inline.hpp"
 #include "runtime/timer.hpp"
@@ -217,9 +218,7 @@
 
 
 // General statistics printing (profiling ...)
-
 void print_statistics() {
-
 #ifdef ASSERT
 
   if (CountRuntimeCalls) {
@@ -315,6 +314,10 @@
     CodeCache::print();
   }
 
+  if (PrintMethodFlushingStatistics) {
+    NMethodSweeper::print();
+  }
+
   if (PrintCodeCache2) {
     MutexLockerEx mu(CodeCache_lock, Mutex::_no_safepoint_check_flag);
     CodeCache::print_internals();
@@ -382,6 +385,10 @@
     CodeCache::print();
   }
 
+  if (PrintMethodFlushingStatistics) {
+    NMethodSweeper::print();
+  }
+
 #ifdef COMPILER2
   if (PrintPreciseBiasedLockingStatistics) {
     OptoRuntime::print_named_counters();
--- a/src/share/vm/runtime/sweeper.cpp	Thu Dec 19 06:09:16 2013 +0100
+++ b/src/share/vm/runtime/sweeper.cpp	Thu Dec 19 14:08:02 2013 +0100
@@ -129,6 +129,7 @@
 
 nmethod* NMethodSweeper::_current                      = NULL; // Current nmethod
 long     NMethodSweeper::_traversals                   = 0;    // Stack scan count, also sweep ID.
+long     NMethodSweeper::_total_nof_code_cache_sweeps  = 0;    // Total number of full sweeps of the code cache
 long     NMethodSweeper::_time_counter                 = 0;    // Virtual time used to periodically invoke sweeper
 long     NMethodSweeper::_last_sweep                   = 0;    // Value of _time_counter when the last sweep happened
 int      NMethodSweeper::_seen                         = 0;    // Nof. nmethod we have currently processed in current pass of CodeCache
@@ -143,13 +144,16 @@
                                                                //   1) alive       -> not_entrant
                                                                //   2) not_entrant -> zombie
                                                                //   3) zombie      -> marked_for_reclamation
+int    NMethodSweeper::_hotness_counter_reset_val       = 0;
 
-int   NMethodSweeper::_total_nof_methods_reclaimed     = 0;    // Accumulated nof methods flushed
-Tickspan NMethodSweeper::_total_time_sweeping;                 // Accumulated time sweeping
-Tickspan NMethodSweeper::_total_time_this_sweep;               // Total time this sweep
-Tickspan NMethodSweeper::_peak_sweep_time;                     // Peak time for a full sweep
-Tickspan NMethodSweeper::_peak_sweep_fraction_time;            // Peak time sweeping one fraction
-int   NMethodSweeper::_hotness_counter_reset_val       = 0;
+long   NMethodSweeper::_total_nof_methods_reclaimed     = 0;    // Accumulated nof methods flushed
+long   NMethodSweeper::_total_nof_c2_methods_reclaimed  = 0;    // Accumulated nof methods flushed
+size_t NMethodSweeper::_total_flushed_size              = 0;    // Total number of bytes flushed from the code cache
+Tickspan  NMethodSweeper::_total_time_sweeping;                 // Accumulated time sweeping
+Tickspan  NMethodSweeper::_total_time_this_sweep;               // Total time this sweep
+Tickspan  NMethodSweeper::_peak_sweep_time;                     // Peak time for a full sweep
+Tickspan  NMethodSweeper::_peak_sweep_fraction_time;            // Peak time sweeping one fraction
+
 
 
 class MarkActivationClosure: public CodeBlobClosure {
@@ -292,6 +296,7 @@
 
     // We are done with sweeping the code cache once.
     if (_sweep_fractions_left == 0) {
+      _total_nof_code_cache_sweeps++;
       _last_sweep = _time_counter;
       // Reset flag; temporarily disables sweeper
       _should_sweep = false;
@@ -378,6 +383,7 @@
   _total_time_sweeping  += sweep_time;
   _total_time_this_sweep += sweep_time;
   _peak_sweep_fraction_time = MAX2(sweep_time, _peak_sweep_fraction_time);
+  _total_flushed_size += freed_memory;
   _total_nof_methods_reclaimed += _flushed_count;
 
   EventSweepCodeCache event(UNTIMED);
@@ -509,6 +515,9 @@
         tty->print_cr("### Nmethod %3d/" PTR_FORMAT " (marked for reclamation) being flushed", nm->compile_id(), nm);
       }
       freed_memory = nm->total_size();
+      if (nm->is_compiled_by_c2()) {
+        _total_nof_c2_methods_reclaimed++;
+      }
       release_nmethod(nm);
       _flushed_count++;
     } else {
@@ -547,6 +556,9 @@
       SWEEP(nm);
       // No inline caches will ever point to osr methods, so we can just remove it
       freed_memory = nm->total_size();
+      if (nm->is_compiled_by_c2()) {
+        _total_nof_c2_methods_reclaimed++;
+      }
       release_nmethod(nm);
       _flushed_count++;
     } else {
@@ -634,3 +646,13 @@
     xtty->end_elem();
   }
 }
+
+void NMethodSweeper::print() {
+  ttyLocker ttyl;
+  tty->print_cr("Code cache sweeper statistics:");
+  tty->print_cr("  Total sweep time:                %1.0lfms", (double)_total_time_sweeping.value()/1000000);
+  tty->print_cr("  Total number of full sweeps:     %ld", _total_nof_code_cache_sweeps);
+  tty->print_cr("  Total number of flushed methods: %ld(%ld C2 methods)", _total_nof_methods_reclaimed,
+                                                    _total_nof_c2_methods_reclaimed);
+  tty->print_cr("  Total size of flushed methods:   " SIZE_FORMAT "kB", _total_flushed_size/K);
+}
--- a/src/share/vm/runtime/sweeper.hpp	Thu Dec 19 06:09:16 2013 +0100
+++ b/src/share/vm/runtime/sweeper.hpp	Thu Dec 19 14:08:02 2013 +0100
@@ -54,28 +54,33 @@
 //     is full.
 
 class NMethodSweeper : public AllStatic {
-  static long      _traversals;                   // Stack scan count, also sweep ID.
-  static long      _time_counter;                 // Virtual time used to periodically invoke sweeper
-  static long      _last_sweep;                   // Value of _time_counter when the last sweep happened
-  static nmethod*  _current;                      // Current nmethod
-  static int       _seen;                         // Nof. nmethod we have currently processed in current pass of CodeCache
-  static int       _flushed_count;                // Nof. nmethods flushed in current sweep
-  static int       _zombified_count;              // Nof. nmethods made zombie in current sweep
-  static int       _marked_for_reclamation_count; // Nof. nmethods marked for reclaim in current sweep
+  static long      _traversals;                     // Stack scan count, also sweep ID.
+  static long      _total_nof_code_cache_sweeps;    // Total number of full sweeps of the code cache
+  static long      _time_counter;                   // Virtual time used to periodically invoke sweeper
+  static long      _last_sweep;                     // Value of _time_counter when the last sweep happened
+  static nmethod*  _current;                        // Current nmethod
+  static int       _seen;                           // Nof. nmethod we have currently processed in current pass of CodeCache
+  static int       _flushed_count;                  // Nof. nmethods flushed in current sweep
+  static int       _zombified_count;                // Nof. nmethods made zombie in current sweep
+  static int       _marked_for_reclamation_count;   // Nof. nmethods marked for reclaim in current sweep
 
-  static volatile int  _sweep_fractions_left;     // Nof. invocations left until we are completed with this pass
-  static volatile int  _sweep_started;            // Flag to control conc sweeper
-  static volatile bool _should_sweep;             // Indicates if we should invoke the sweeper
-  static volatile int _bytes_changed;             // Counts the total nmethod size if the nmethod changed from:
-                                                  //   1) alive       -> not_entrant
-                                                  //   2) not_entrant -> zombie
-                                                  //   3) zombie      -> marked_for_reclamation
+  static volatile int  _sweep_fractions_left;       // Nof. invocations left until we are completed with this pass
+  static volatile int  _sweep_started;              // Flag to control conc sweeper
+  static volatile bool _should_sweep;               // Indicates if we should invoke the sweeper
+  static volatile int  _bytes_changed;              // Counts the total nmethod size if the nmethod changed from:
+                                                    //   1) alive       -> not_entrant
+                                                    //   2) not_entrant -> zombie
+                                                    //   3) zombie      -> marked_for_reclamation
   // Stat counters
-  static int       _total_nof_methods_reclaimed;  // Accumulated nof methods flushed
-  static Tickspan  _total_time_sweeping;          // Accumulated time sweeping
-  static Tickspan  _total_time_this_sweep;        // Total time this sweep
-  static Tickspan  _peak_sweep_time;              // Peak time for a full sweep
-  static Tickspan  _peak_sweep_fraction_time;     // Peak time sweeping one fraction
+  static long      _total_nof_methods_reclaimed;    // Accumulated nof methods flushed
+  static long      _total_nof_c2_methods_reclaimed; // Accumulated nof C2-compiled methods flushed
+  static size_t    _total_flushed_size;             // Total size of flushed methods
+  static int       _hotness_counter_reset_val;
+
+  static Tickspan  _total_time_sweeping;            // Accumulated time sweeping
+  static Tickspan  _total_time_this_sweep;          // Total time this sweep
+  static Tickspan  _peak_sweep_time;                // Peak time for a full sweep
+  static Tickspan  _peak_sweep_fraction_time;       // Peak time sweeping one fraction
 
   static int  process_nmethod(nmethod *nm);
   static void release_nmethod(nmethod* nm);
@@ -83,8 +88,6 @@
   static bool sweep_in_progress();
   static void sweep_code_cache();
 
-  static int _hotness_counter_reset_val;
-
  public:
   static long traversal_count()              { return _traversals; }
   static int  total_nof_methods_reclaimed()  { return _total_nof_methods_reclaimed; }
@@ -105,10 +108,10 @@
   static void mark_active_nmethods();      // Invoked at the end of each safepoint
   static void possibly_sweep();            // Compiler threads call this to sweep
 
-  static int sort_nmethods_by_hotness(nmethod** nm1, nmethod** nm2);
   static int hotness_counter_reset_val();
   static void report_state_change(nmethod* nm);
   static void possibly_enable_sweeper();
+  static void print();   // Printing/debugging
 };
 
 #endif // SHARE_VM_RUNTIME_SWEEPER_HPP