add performance counting mechanism for MRI debug/tuning purpose.

* How to enable this feature?
  * define USE_DEBUG_COUNTER as 1.
  * you can disable to output the result with
    RUBY_DEBUG_COUNTER_DISABLE environment variable
    even if USE_DEBUG_COUNTER == 1.

* How to add new counter?
  * add COUNTER(<name>) line on debug_counter.h.
  * include "debug_counter.h"
  * insert RB_DEBUG_COUNTER_INC(<name>) line on your favorite place.

* counter output example:
  [RUBY_DEBUG_COUNTER]    mc_inline_hit   999
  [RUBY_DEBUG_COUNTER]    mc_inline_miss  3
  [RUBY_DEBUG_COUNTER]    mc_global_hit   23
  [RUBY_DEBUG_COUNTER]    mc_global_miss  273
  [RUBY_DEBUG_COUNTER]    mc_global_state_miss    3
  [RUBY_DEBUG_COUNTER]    mc_class_serial_miss    0
  [RUBY_DEBUG_COUNTER]    mc_cme_complement       0
  [RUBY_DEBUG_COUNTER]    mc_cme_complement_hit   0
  [RUBY_DEBUG_COUNTER]    mc_search_super 1384
  [RUBY_DEBUG_COUNTER]    ivar_get_hit    0
  [RUBY_DEBUG_COUNTER]    ivar_get_miss   0
  [RUBY_DEBUG_COUNTER]    ivar_set_hit    0
  [RUBY_DEBUG_COUNTER]    ivar_set_miss   0
  [RUBY_DEBUG_COUNTER]    ivar_get        431
  [RUBY_DEBUG_COUNTER]    ivar_set        465

  * mc_... is related to method caching.
  * ivar_... is related to instance variable accesses.

* compare with dtrace/system tap features, there are completely
  no performacne penalties when it is disabled.

* This feature is supported only on __GNUC__ compilers.


git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@57676 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

common.mk

@@ -79,6 +79,7 @@ COMMONOBJS    = array.$(OBJEXT) \
 		complex.$(OBJEXT) \
 		cont.$(OBJEXT) \
 		debug.$(OBJEXT) \
+		debug_counter.$(OBJEXT) \
 		dir.$(OBJEXT) \
 		dln_find.$(OBJEXT) \
 		encoding.$(OBJEXT) \
@@ -849,10 +850,15 @@ incs: $(INSNS) {$(VPATH)}node_name.inc {$(VPATH)}known_errors.inc \
       {$(VPATH)}vm_call_iseq_optimized.inc $(srcdir)/revision.h \
       $(REVISION_H) \
       $(UNICODE_DATA_HEADERS) $(srcdir)/enc/jis/props.h \
-      {$(VPATH)}id.h {$(VPATH)}probes.dmyh
+      {$(VPATH)}id.h {$(VPATH)}probes.dmyh \
+      {$(VPATH)}debug_counter_names.inc
 
 insns: $(INSNS)
 
+debug_counter_names.inc: $(srcdir)/tool/debug_counter.rb $(srcdir)/debug_counter.h
+	$(ECHO) generating $@
+	$(Q) $(BASERUBY) $(srcdir)/tool/debug_counter.rb $(srcdir)/debug_counter.h > $@
+
 id.h: $(srcdir)/tool/generic_erb.rb $(srcdir)/template/id.h.tmpl $(srcdir)/defs/id.def
 	$(ECHO) generating $@
 	$(Q) $(BASERUBY) $(srcdir)/tool/generic_erb.rb --output=$@ \
@@ -1420,6 +1426,9 @@ debug.$(OBJEXT): {$(VPATH)}util.h
 debug.$(OBJEXT): {$(VPATH)}vm_core.h
 debug.$(OBJEXT): {$(VPATH)}vm_debug.h
 debug.$(OBJEXT): {$(VPATH)}vm_opts.h
+debug_counter.$(OBJEXT): {$(VPATH)}debug_counter.h
+debug_counter.$(OBJEXT): {$(VPATH)}debug_counter_names.inc
+debug_counter.$(OBJEXT): {$(VPATH)}debug_counter.c
 dir.$(OBJEXT): $(hdrdir)/ruby/ruby.h
 dir.$(OBJEXT): $(top_srcdir)/include/ruby.h
 dir.$(OBJEXT): {$(VPATH)}config.h
@@ -2534,6 +2543,7 @@ variable.$(OBJEXT): $(top_srcdir)/include/ruby.h
 variable.$(OBJEXT): {$(VPATH)}config.h
 variable.$(OBJEXT): {$(VPATH)}constant.h
 variable.$(OBJEXT): {$(VPATH)}defines.h
+variable.$(OBJEXT): {$(VPATH)}debug_counter.h
 variable.$(OBJEXT): {$(VPATH)}encoding.h
 variable.$(OBJEXT): {$(VPATH)}id.h
 variable.$(OBJEXT): {$(VPATH)}id_table.h
@@ -2568,6 +2578,7 @@ vm.$(OBJEXT): {$(VPATH)}constant.h
 vm.$(OBJEXT): {$(VPATH)}defines.h
 vm.$(OBJEXT): {$(VPATH)}encoding.h
 vm.$(OBJEXT): {$(VPATH)}eval_intern.h
+vm.$(OBJEXT): {$(VPATH)}debug_counter.h
 vm.$(OBJEXT): {$(VPATH)}gc.h
 vm.$(OBJEXT): {$(VPATH)}id.h
 vm.$(OBJEXT): {$(VPATH)}id_table.h

debug_counter.c

@@ -0,0 +1,39 @@
+/**********************************************************************
+
+  debug_counter.c -
+
+  created at: Tue Feb 21 16:51:18 2017
+
+  Copyright (C) 2017 Koichi Sasada
+
+**********************************************************************/
+
+#include "debug_counter.h"
+#include <stdio.h>
+
+#if USE_DEBUG_COUNTER
+
+/* do not modify manually. use a script above */
+const char * const debug_counter_names[] = {
+#include "debug_counter_names.inc"
+    ""
+};
+
+size_t rb_debug_counter[RB_DEBUG_COUNTER_MAX + 1];
+
+__attribute__((destructor))
+static void
+rb_debug_counter_show_results(void)
+{
+    const char *env = getenv("RUBY_DEBUG_COUNTER_DISABLE");
+    if (env == NULL || strcmp("1", env) != 0) {
+	int i;
+	for (i=0; i<RB_DEBUG_COUNTER_MAX; i++) {
+	    fprintf(stderr, "[RUBY_DEBUG_COUNTER]\t%s\t%"PRIuSIZE"\n",
+		    debug_counter_names[i],
+		    rb_debug_counter[i]);
+	}
+    }
+}
+
+#endif /* USE_DEBUG_COUNTER */

debug_counter.h

@@ -0,0 +1,67 @@
+/**********************************************************************
+
+  debug_counter.h -
+
+  created at: Tue Feb 21 16:51:18 2017
+
+  Copyright (C) 2017 Koichi Sasada
+
+**********************************************************************/
+
+#ifndef RUBY_DEBUG_COUNTER_H
+#define RUBY_DEBUG_COUNTER_H 1
+
+#ifndef USE_DEBUG_COUNTER
+#define USE_DEBUG_COUNTER 0
+#endif
+
+#if !defined(__GNUC__) && USE_DEBUG_COUNTER
+#error "USE_DEBUG_COUNTER is not supported by other than __GNUC__"
+#endif
+
+enum rb_debug_counter_type {
+#define COUNTER(name) RB_DEBUG_COUNTER_##name
+    COUNTER(mc_inline_hit),
+    COUNTER(mc_inline_miss),
+    COUNTER(mc_global_hit),
+    COUNTER(mc_global_miss),
+    COUNTER(mc_global_state_miss),
+    COUNTER(mc_class_serial_miss),
+    COUNTER(mc_cme_complement),
+    COUNTER(mc_cme_complement_hit),
+    COUNTER(mc_search_super),
+    COUNTER(ivar_get_hit),
+    COUNTER(ivar_get_miss),
+    COUNTER(ivar_set_hit),
+    COUNTER(ivar_set_miss),
+    COUNTER(ivar_get),
+    COUNTER(ivar_set),
+    RB_DEBUG_COUNTER_MAX
+#undef COUNTER
+};
+
+#if USE_DEBUG_COUNTER
+#include "ruby/ruby.h"
+
+extern size_t rb_debug_counter[RB_DEBUG_COUNTER_MAX + 1];
+
+inline static int
+rb_debug_counter_add(enum rb_debug_counter_type type, int add, int cond)
+{
+    if (cond) {
+	rb_debug_counter[(int)type] += add;
+    }
+    return cond;
+}
+
+#define RB_DEBUG_COUNTER_INC(type)                rb_debug_counter_add(RB_DEBUG_COUNTER_##type, 1, 1)
+#define RB_DEBUG_COUNTER_INC_UNLESS(type, cond) (!rb_debug_counter_add(RB_DEBUG_COUNTER_##type, 1, !(cond)))
+#define RB_DEBUG_COUNTER_INC_IF(type, cond)       rb_debug_counter_add(RB_DEBUG_COUNTER_##type, 1, (cond))
+
+#else
+#define RB_DEBUG_COUNTER_INC(type)              ((void)0)
+#define RB_DEBUG_COUNTER_INC_UNLESS(type, cond) (cond)
+#define RB_DEBUG_COUNTER_INC_IF(type, cond)     (cond)
+#endif
+
+#endif /* RUBY_DEBUG_COUNTER_H */

tool/debug_counter.rb

@@ -0,0 +1,6 @@
+
+ARGF.each_line{|line|
+  if /^\s+COUNTER\((.+)\),$/ =~ line
+    puts "\"#{$1}\","
+  end
+}

variable.c

@@ -19,6 +19,7 @@
 #include "id.h"
 #include "ccan/list/list.h"
 #include "id_table.h"
+#include "debug_counter.h"
 
 struct rb_id_table *rb_global_tbl;
 static ID autoload, classpath, tmp_classpath, classid;
@@ -1209,6 +1210,7 @@ VALUE
 rb_ivar_get(VALUE obj, ID id)
 {
     VALUE iv = rb_ivar_lookup(obj, id, Qundef);
+    RB_DEBUG_COUNTER_INC(ivar_get);
 
     if (iv == Qundef) {
 	if (RTEST(ruby_verbose))
@@ -1315,6 +1317,8 @@ rb_ivar_set(VALUE obj, ID id, VALUE val)
     struct ivar_update ivup;
     uint32_t i, len;
 
+    RB_DEBUG_COUNTER_INC(ivar_set);
+
     rb_check_frozen(obj);
 
     switch (BUILTIN_TYPE(obj)) {

vm_insnhelper.c

@@ -16,6 +16,7 @@
 #include "probes.h"
 #include "probes_helper.h"
 #include "ruby/config.h"
+#include "debug_counter.h"
 
 /* control stack frame */
 
@@ -894,6 +895,7 @@ vm_getivar(VALUE obj, ID id, IC ic, struct rb_call_cache *cc, int is_attr)
 		    rb_warning("instance variable %"PRIsVALUE" not initialized", QUOTE_ID(id));
 		val = Qnil;
 	    }
+	    RB_DEBUG_COUNTER_INC(ivar_get_hit);
 	    return val;
 	}
 	else {
@@ -918,6 +920,8 @@ vm_getivar(VALUE obj, ID id, IC ic, struct rb_call_cache *cc, int is_attr)
 	}
     }
 #endif	/* USE_IC_FOR_IVAR */
+    RB_DEBUG_COUNTER_INC(ivar_get_miss);
+
     if (is_attr)
 	return rb_attr_get(obj, id);
     return rb_ivar_get(obj, id);
@@ -941,6 +945,7 @@ vm_setivar(VALUE obj, ID id, VALUE val, IC ic, struct rb_call_cache *cc, int is_
 
 	    if (index < ROBJECT_NUMIV(obj)) {
 		RB_OBJ_WRITE(obj, &ptr[index], val);
+		RB_DEBUG_COUNTER_INC(ivar_set_hit);
 		return val; /* inline cache hit */
 	    }
 	}
@@ -963,6 +968,7 @@ vm_setivar(VALUE obj, ID id, VALUE val, IC ic, struct rb_call_cache *cc, int is_
 	}
     }
 #endif	/* USE_IC_FOR_IVAR */
+    RB_DEBUG_COUNTER_INC(ivar_set_miss);
     return rb_ivar_set(obj, id, val);
 }
 
@@ -1220,13 +1226,17 @@ vm_search_method(const struct rb_call_info *ci, struct rb_call_cache *cc, VALUE
     VALUE klass = CLASS_OF(recv);
 
 #if OPT_INLINE_METHOD_CACHE
-    if (LIKELY(GET_GLOBAL_METHOD_STATE() == cc->method_state && RCLASS_SERIAL(klass) == cc->class_serial)) {
+    if (LIKELY(RB_DEBUG_COUNTER_INC_UNLESS(mc_global_state_miss,
+					   GET_GLOBAL_METHOD_STATE() == cc->method_state) &&
+	       RB_DEBUG_COUNTER_INC_UNLESS(mc_class_serial_miss,
+					   RCLASS_SERIAL(klass) == cc->class_serial))) {
 	/* cache hit! */
 	VM_ASSERT(cc->call != NULL);
+	RB_DEBUG_COUNTER_INC(mc_inline_hit);
 	return;
     }
+    RB_DEBUG_COUNTER_INC(mc_inline_miss);
 #endif
-
     cc->me = rb_callable_method_entry(klass, ci->mid);
     VM_ASSERT(callable_method_entry_p(cc->me));
     cc->call = vm_call_general;

vm_method.c

@@ -695,6 +695,7 @@ search_method(VALUE klass, ID id, VALUE *defined_class_ptr)
     rb_method_entry_t *me;
 
     for (me = 0; klass; klass = RCLASS_SUPER(klass)) {
+	RB_DEBUG_COUNTER_INC(mc_search_super);
 	if ((me = lookup_method_table(klass, id)) != 0) break;
     }
 
@@ -778,10 +779,12 @@ method_entry_get(VALUE klass, ID id, VALUE *defined_class_ptr)
 	verify_method_cache(klass, id, ent->defined_class, ent->me);
 #endif
 	if (defined_class_ptr) *defined_class_ptr = ent->defined_class;
+	RB_DEBUG_COUNTER_INC(mc_global_hit);
 	return ent->me;
     }
 #endif
 
+    RB_DEBUG_COUNTER_INC(mc_global_miss);
     return method_entry_get_without_cache(klass, id, defined_class_ptr);
 }
 
@@ -798,6 +801,7 @@ prepare_callable_method_entry(VALUE defined_class, ID id, const rb_method_entry_
     const rb_callable_method_entry_t *cme;
 
     if (me && me->defined_class == 0) {
+	RB_DEBUG_COUNTER_INC(mc_cme_complement);
 	VM_ASSERT(RB_TYPE_P(defined_class, T_ICLASS) || RB_TYPE_P(defined_class, T_MODULE));
 	VM_ASSERT(me->defined_class == 0);
 
@@ -806,6 +810,7 @@ prepare_callable_method_entry(VALUE defined_class, ID id, const rb_method_entry_
 	}
 
 	if (rb_id_table_lookup(mtbl, id, (VALUE *)&me)) {
+	    RB_DEBUG_COUNTER_INC(mc_cme_complement_hit);
 	    cme = (rb_callable_method_entry_t *)me;
 	    VM_ASSERT(callable_method_entry_p(cme));
 	}