ruby-changes:45604
From: ko1 <ko1@a...>
Date: Tue, 21 Feb 2017 17:18:21 +0900 (JST)
Subject: [ruby-changes:45604] ko1:r57676 (trunk): add performance counting mechanism for MRI debug/tuning purpose.
ko1 2017-02-21 17:18:15 +0900 (Tue, 21 Feb 2017) New Revision: 57676 https://svn.ruby-lang.org/cgi-bin/viewvc.cgi?view=revision&revision=57676 Log: 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. Added files: trunk/debug_counter.c trunk/debug_counter.h trunk/tool/debug_counter.rb Modified files: trunk/common.mk trunk/variable.c trunk/vm_insnhelper.c trunk/vm_method.c Index: vm_insnhelper.c =================================================================== --- vm_insnhelper.c (revision 57675) +++ vm_insnhelper.c (revision 57676) @@ -16,6 +16,7 @@ https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L16 #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, stru https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L895 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, stru https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L920 } } #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, https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L945 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, https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L968 } } #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_in https://github.com/ruby/ruby/blob/trunk/vm_insnhelper.c#L1226 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; Index: vm_method.c =================================================================== --- vm_method.c (revision 57675) +++ vm_method.c (revision 57676) @@ -695,6 +695,7 @@ search_method(VALUE klass, ID id, VALUE https://github.com/ruby/ruby/blob/trunk/vm_method.c#L695 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, VAL https://github.com/ruby/ruby/blob/trunk/vm_method.c#L779 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 defi https://github.com/ruby/ruby/blob/trunk/vm_method.c#L801 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 defi https://github.com/ruby/ruby/blob/trunk/vm_method.c#L810 } 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)); } Index: debug_counter.c =================================================================== --- debug_counter.c (revision 0) +++ debug_counter.c (revision 57676) @@ -0,0 +1,39 @@ https://github.com/ruby/ruby/blob/trunk/debug_counter.c#L1 +/********************************************************************** + + 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 */ Index: debug_counter.h =================================================================== --- debug_counter.h (revision 0) +++ debug_counter.h (revision 57676) @@ -0,0 +1,67 @@ https://github.com/ruby/ruby/blob/trunk/debug_counter.h#L1 +/********************************************************************** + + 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 */ Index: tool/debug_counter.rb =================================================================== --- tool/debug_counter.rb (revision 0) +++ tool/debug_counter.rb (revision 57676) @@ -0,0 +1,6 @@ https://github.com/ruby/ruby/blob/trunk/tool/debug_counter.rb#L1 + +ARGF.each_line{|line| + if /^\s+COUNTER\((.+)\),$/ =~ line + puts "\"#{$1}\"," + end +} Index: variable.c =================================================================== --- variable.c (revision 57675) +++ variable.c (revision 57676) @@ -19,6 +19,7 @@ https://github.com/ruby/ruby/blob/trunk/variable.c#L19 #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 https://github.com/ruby/ruby/blob/trunk/variable.c#L1210 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) https://github.com/ruby/ruby/blob/trunk/variable.c#L1317 struct ivar_update ivup; uint32_t i, len; + RB_DEBUG_COUNTER_INC(ivar_set); + rb_check_frozen(obj); switch (BUILTIN_TYPE(obj)) { Index: common.mk =================================================================== --- common.mk (revision 57675) +++ common.mk (revision 57676) @@ -79,6 +79,7 @@ COMMONOBJS = array.$(OBJEXT) \ https://github.com/ruby/ruby/blob/trunk/common.mk#L79 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 { https://github.com/ruby/ruby/blob/trunk/common.mk#L850 {$(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 https://github.com/ruby/ruby/blob/trunk/common.mk#L1426 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)/includ https://github.com/ruby/ruby/blob/trunk/common.mk#L2543 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 https://github.com/ruby/ruby/blob/trunk/common.mk#L2578 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 -- ML: ruby-changes@q... Info: http://www.atdot.net/~ko1/quickml/