Add `hit` instrumentation events and add log_stat!

CHANGELOG.md

@@ -1,5 +1,7 @@
 # Unreleased
 
+* `Bootsnap.instrumentation` now receive `:hit` events.
+* Add `Bootsnap.log_stats!` to print hit rate statistics on process exit. Can also be enabled with `BOOTSNAP_STATS=1`.
 * Revalidate stale cache entries by digesting the source content.
   This should significantly improve performance in environments where `mtime` isn't preserved (e.g. CI systems doing a git clone, etc).
   See #468.

README.md

@@ -81,6 +81,7 @@ well together.
 - `DISABLE_BOOTSNAP_COMPILE_CACHE` allows to disable ISeq and YAML caches.
 - `BOOTSNAP_READONLY` configure bootsnap to not update the cache on miss or stale entries.
 - `BOOTSNAP_LOG` configure bootsnap to log all caches misses to STDERR.
+- `BOOTSNAP_STATS` log hit rate statistics on exit. Can't be used if `BOOTSNAP_LOG` is enabled.
 - `BOOTSNAP_IGNORE_DIRECTORIES` a comma separated list of directories that shouldn't be scanned.
   Useful when you have large directories of non-ruby files inside `$LOAD_PATH`.
   It defaults to ignore any directory named `node_modules`.
@@ -99,8 +100,8 @@ Bootsnap cache misses can be monitored though a callback:
 Bootsnap.instrumentation = ->(event, path) { puts "#{event} #{path}" }
 ```
 
-`event` is either `:miss`, `:stale` or `:revalidated`. You can also call `Bootsnap.log!` as a shortcut to
+`event` is either `:hit`, `:miss`, `:stale` or `:revalidated`.
-log all events to STDERR.
+You can also call `Bootsnap.log!` as a shortcut to log all events to STDERR.
 
 To turn instrumentation back off you can set it to nil:
 

ext/bootsnap/bootsnap.c

@@ -93,9 +93,7 @@ static VALUE rb_mBootsnap_CompileCache;
 static VALUE rb_mBootsnap_CompileCache_Native;
 static VALUE rb_cBootsnap_CompileCache_UNCOMPILABLE;
 static ID instrumentation_method;
-static VALUE sym_miss;
+static VALUE sym_hit, sym_miss, sym_stale, sym_revalidated;
-static VALUE sym_stale;
-static VALUE sym_revalidated;
 static bool instrumentation_enabled = false;
 static bool readonly = false;
 
@@ -177,14 +175,10 @@ Init_bootsnap(void)
 
   instrumentation_method = rb_intern("_instrument");
 
+  sym_hit = ID2SYM(rb_intern("hit"));
   sym_miss = ID2SYM(rb_intern("miss"));
-  rb_global_variable(&sym_miss);
-
   sym_stale = ID2SYM(rb_intern("stale"));
-  rb_global_variable(&sym_stale);
-
   sym_revalidated = ID2SYM(rb_intern("revalidated"));
-  rb_global_variable(&sym_revalidated);
 
   rb_define_module_function(rb_mBootsnap, "instrumentation_enabled=", bs_instrumentation_enabled_set, 1);
   rb_define_module_function(rb_mBootsnap_CompileCache_Native, "readonly=", bs_readonly_set, 1);
@@ -746,6 +740,7 @@ bs_fetch(char * path, VALUE path_v, char * cache_path, VALUE handler, VALUE args
   int res, valid_cache = 0, exception_tag = 0;
   const char * errno_provenance = NULL;
 
+  VALUE status = Qfalse;
   VALUE input_data = Qfalse;   /* data read from source file, e.g. YAML or ruby source */
   VALUE storage_data; /* compiled data, e.g. msgpack / binary iseq */
   VALUE output_data;  /* return data, e.g. ruby hash or loaded iseq */
@@ -774,6 +769,7 @@ bs_fetch(char * path, VALUE path_v, char * cache_path, VALUE handler, VALUE args
 
     switch(cache_key_equal_fast_path(&current_key, &cached_key)) {
     case hit:
+      status = sym_hit;
       valid_cache = true;
       break;
     case miss:
@@ -794,13 +790,13 @@ bs_fetch(char * path, VALUE path_v, char * cache_path, VALUE handler, VALUE args
               goto fail_errno;
           }
         }
-        bs_instrumentation(sym_revalidated, path_v);
+        status = sym_revalidated;
       }
       break;
     };
 
     if (!valid_cache) {
-      bs_instrumentation(sym_stale, path_v);
+      status = sym_stale;
     }
   }
 
@@ -885,6 +881,7 @@ bs_fetch(char * path, VALUE path_v, char * cache_path, VALUE handler, VALUE args
   goto succeed; /* output_data is now the correct return. */
 
 #define CLEANUP \
+  if (status != Qfalse) bs_instrumentation(status, path_v); \
   if (current_fd >= 0)  close(current_fd); \
   if (cache_fd >= 0)    close(cache_fd);
 
@@ -953,8 +950,6 @@ bs_precompile(char * path, VALUE path_v, char * cache_path, VALUE handler)
          if (update_cache_key(&current_key, cache_fd, &errno_provenance)) {
              goto fail;
          }
-
-         bs_instrumentation(sym_revalidated, path_v);
       }
       break;
     };

lib/bootsnap.rb

@@ -11,6 +11,16 @@ module Bootsnap
   class << self
     attr_reader :logger
 
+    def log_stats!
+      stats = {hit: 0, revalidated: 0, miss: 0, stale: 0}
+      self.instrumentation = ->(event, _path) { stats[event] += 1 }
+      Kernel.at_exit do
+        stats.each do |event, count|
+          $stderr.puts "bootsnap #{event}: #{count}"
+        end
+      end
+    end
+
     def log!
       self.logger = $stderr.method(:puts)
     end
@@ -18,9 +28,9 @@ module Bootsnap
     def logger=(logger)
       @logger = logger
       self.instrumentation = if logger.respond_to?(:debug)
-        ->(event, path) { @logger.debug("[Bootsnap] #{event} #{path}") }
+        ->(event, path) { @logger.debug("[Bootsnap] #{event} #{path}") unless event == :hit }
       else
-        ->(event, path) { @logger.call("[Bootsnap] #{event} #{path}") }
+        ->(event, path) { @logger.call("[Bootsnap] #{event} #{path}") unless event == :hit }
       end
     end
 
@@ -110,6 +120,8 @@ module Bootsnap
 
         if ENV["BOOTSNAP_LOG"]
           log!
+        elsif ENV["BOOTSNAP_STATS"]
+          log_stats!
         end
       end
     end

test/compile_cache_test.rb

@@ -205,7 +205,7 @@ class CompileCacheTest < Minitest::Test
 
     load(file_path)
 
-    assert_equal [], calls
+    assert_equal [[:hit, "a.rb"]], calls
   end
 
   def test_instrumentation_miss