[ondemand] trace cache operations

Summary:
Count the following:
- how many procedures were *actually* analyzed (i.e. some checkers ran
  on them)
- how many times an analysis result was retrieved from the local cache
  and how many times it was missed

Reviewed By: skcho

Differential Revision: D16561867

fbshipit-source-id: 8c43ce13c

infer/src/backend/BackendStats.ml

@@ -17,7 +17,10 @@ include struct
     ; mutable summary_read_from_disk: int
     ; mutable summary_cache_hits: int
     ; mutable summary_cache_misses: int
-    ; mutable summary_has_model_queries: int }
+    ; mutable summary_has_model_queries: int
+    ; mutable ondemand_procs_analyzed: int
+    ; mutable ondemand_local_cache_hits: int
+    ; mutable ondemand_local_cache_misses: int }
   [@@deriving fields]
 end
 
@@ -26,7 +29,10 @@ let global_stats =
   ; summary_read_from_disk= 0
   ; summary_cache_hits= 0
   ; summary_cache_misses= 0
-  ; summary_has_model_queries= 0 }
+  ; summary_has_model_queries= 0
+  ; ondemand_procs_analyzed= 0
+  ; ondemand_local_cache_hits= 0
+  ; ondemand_local_cache_misses= 0 }
 
 
 let get () = global_stats
@@ -49,16 +55,26 @@ let incr_summary_cache_misses () = incr Fields.summary_cache_misses
 
 let incr_summary_has_model_queries () = incr Fields.summary_has_model_queries
 
+let incr_ondemand_procs_analyzed () = incr Fields.ondemand_procs_analyzed
+
+let incr_ondemand_local_cache_hits () = incr Fields.ondemand_local_cache_hits
+
+let incr_ondemand_local_cache_misses () = incr Fields.ondemand_local_cache_misses
+
 let copy from ~into : unit =
   let { summary_file_try_load
       ; summary_read_from_disk
       ; summary_cache_hits
       ; summary_cache_misses
-      ; summary_has_model_queries } =
+      ; summary_has_model_queries
+      ; ondemand_procs_analyzed
+      ; ondemand_local_cache_hits
+      ; ondemand_local_cache_misses } =
     from
   in
   Fields.Direct.set_all_mutable_fields into ~summary_file_try_load ~summary_read_from_disk
-    ~summary_cache_hits ~summary_cache_misses ~summary_has_model_queries
+    ~summary_cache_hits ~summary_cache_misses ~summary_has_model_queries ~ondemand_procs_analyzed
+    ~ondemand_local_cache_hits ~ondemand_local_cache_misses
 
 
 let merge stats1 stats2 =
@@ -67,7 +83,10 @@ let merge stats1 stats2 =
   ; summary_cache_hits= stats1.summary_cache_hits + stats2.summary_cache_hits
   ; summary_cache_misses= stats1.summary_cache_misses + stats2.summary_cache_misses
   ; summary_has_model_queries= stats1.summary_has_model_queries + stats2.summary_has_model_queries
-  }
+  ; ondemand_procs_analyzed= stats1.ondemand_procs_analyzed + stats2.ondemand_procs_analyzed
+  ; ondemand_local_cache_hits= stats1.ondemand_local_cache_hits + stats2.ondemand_local_cache_hits
+  ; ondemand_local_cache_misses=
+      stats1.ondemand_local_cache_misses + stats2.ondemand_local_cache_misses }
 
 
 let initial =
@@ -75,7 +94,10 @@ let initial =
   ; summary_read_from_disk= 0
   ; summary_cache_hits= 0
   ; summary_cache_misses= 0
-  ; summary_has_model_queries= 0 }
+  ; summary_has_model_queries= 0
+  ; ondemand_procs_analyzed= 0
+  ; ondemand_local_cache_hits= 0
+  ; ondemand_local_cache_misses= 0 }
 
 
 let reset () = copy initial ~into:global_stats
@@ -89,15 +111,20 @@ let pp f stats =
   let pp_int_field stats f field =
     F.fprintf f "%s= %d@;" (Field.name field) (Field.get field stats)
   in
-  let pp_cache_hits stats f cache_hits_field =
-    F.fprintf f "%s= %d (%t)@;" (Field.name cache_hits_field) stats.summary_cache_hits
-      (pp_hit_percent stats.summary_cache_hits stats.summary_cache_misses)
+  let pp_cache_hits stats cache_misses f cache_hits_field =
+    let cache_hits = Field.get cache_hits_field stats in
+    F.fprintf f "%s= %d (%t)@;" (Field.name cache_hits_field) cache_hits
+      (pp_hit_percent cache_hits cache_misses)
   in
   let pp_stats stats f =
     Fields.iter ~summary_file_try_load:(pp_int_field stats f)
-      ~summary_read_from_disk:(pp_int_field stats f) ~summary_cache_hits:(pp_cache_hits stats f)
+      ~summary_read_from_disk:(pp_int_field stats f)
+      ~summary_cache_hits:(pp_cache_hits stats stats.summary_cache_misses f)
       ~summary_cache_misses:(pp_int_field stats f)
       ~summary_has_model_queries:(pp_int_field stats f)
+      ~ondemand_procs_analyzed:(pp_int_field stats f)
+      ~ondemand_local_cache_hits:(pp_cache_hits stats stats.ondemand_local_cache_misses f)
+      ~ondemand_local_cache_misses:(pp_int_field stats f)
   in
   F.fprintf f "@[Backend stats:@\n@[<v2>  %t@]@]@." (pp_stats stats)
 
@@ -109,6 +136,7 @@ let log_to_scuba stats =
   let entries =
     Fields.to_list ~summary_file_try_load:create_counter ~summary_read_from_disk:create_counter
       ~summary_cache_hits:create_counter ~summary_cache_misses:create_counter
-      ~summary_has_model_queries:create_counter
+      ~summary_has_model_queries:create_counter ~ondemand_procs_analyzed:create_counter
+      ~ondemand_local_cache_hits:create_counter ~ondemand_local_cache_misses:create_counter
   in
   ScubaLogging.log_many entries

infer/src/backend/BackendStats.mli

@@ -25,6 +25,12 @@ val incr_summary_cache_misses : unit -> unit
 val incr_summary_has_model_queries : unit -> unit
 (** someone asked if a proc name has a biabduction model *)
 
+val incr_ondemand_procs_analyzed : unit -> unit
+
+val incr_ondemand_local_cache_hits : unit -> unit
+
+val incr_ondemand_local_cache_misses : unit -> unit
+
 val reset : unit -> unit
 (** reset all stats *)
 

infer/src/backend/InferAnalyze.ml

@@ -13,7 +13,7 @@ module F = Format
 module L = Logging
 
 let clear_caches () =
-  Ondemand.clear_cache () ;
+  Ondemand.LocalCache.clear () ;
   Summary.OnDisk.clear_cache () ;
   Typ.Procname.SQLite.clear_cache ()
 

infer/src/backend/SpecsFiles.ml

@@ -68,5 +68,5 @@ let delete pname =
   let filename = Summary.OnDisk.specs_filename_of_procname pname |> DB.filename_to_string in
   (* Unix_error is raised if the file isn't present so do nothing in this case *)
   (try Unix.unlink filename with Unix.Unix_error _ -> ()) ;
-  Ondemand.remove_from_cache pname ;
+  Ondemand.LocalCache.remove pname ;
   Summary.OnDisk.remove_from_cache pname

infer/src/backend/ondemand.ml

@@ -14,11 +14,23 @@ module F = Format
 
 let exe_env_ref = ref None
 
-let cached_results = lazy (Typ.Procname.Hash.create 128)
+module LocalCache = struct
+  let results = lazy (Typ.Procname.Hash.create 128)
 
-let clear_cache () = Typ.Procname.Hash.clear (Lazy.force cached_results)
+  let clear () = Typ.Procname.Hash.clear (Lazy.force results)
 
-let remove_from_cache pname = Typ.Procname.Hash.remove (Lazy.force cached_results) pname
+  let remove pname = Typ.Procname.Hash.remove (Lazy.force results) pname
+
+  let get proc_name =
+    let summ_opt_opt = Typ.Procname.Hash.find_opt (Lazy.force results) proc_name in
+    if Option.is_some summ_opt_opt then BackendStats.incr_ondemand_local_cache_hits ()
+    else BackendStats.incr_ondemand_local_cache_misses () ;
+    summ_opt_opt
+
+
+  let add proc_name summary_option =
+    Typ.Procname.Hash.add (Lazy.force results) proc_name summary_option
+end
 
 let set_exe_env (env : Exe_env.t) = exe_env_ref := Some env
 
@@ -128,6 +140,7 @@ let restore_global_state st =
 let logged_error = ref false
 
 let analyze callee_summary =
+  BackendStats.incr_ondemand_procs_analyzed () ;
   let callee_pdesc = Summary.get_proc_desc callee_summary in
   let exe_env = Option.value_exn !exe_env_ref in
   let proc_name = Procdesc.get_proc_name callee_pdesc in
@@ -331,31 +344,32 @@ let analyze_callee ?caller_summary callee =
   register_callee ?caller_summary callee_pname ;
   if is_active callee_pname then None
   else
-    let cache = Lazy.force cached_results in
-    try Typ.Procname.Hash.find cache callee_pname
-    with Caml.Not_found ->
-      let callee_summary_option, update_memcached =
-        match memcache_get callee_pname with
-        | Some summ_opt ->
-            (summ_opt, false)
-        | None ->
-            if callee_should_be_analyzed callee then
-              match get_callee_proc_desc callee with
-              | Some callee_pdesc ->
-                  ( Some
-                      (run_proc_analysis
-                         ~caller_pdesc:(Option.map ~f:Summary.get_proc_desc caller_summary)
-                         callee_pdesc)
-                  , true )
-              | None ->
-                  (Summary.OnDisk.get callee_pname, true)
-            else (
-              EventLogger.log_skipped_pname (F.asprintf "%a" Typ.Procname.pp callee_pname) ;
-              (Summary.OnDisk.get callee_pname, true) )
-      in
-      if update_memcached then memcache_set callee_pname callee_summary_option ;
-      Typ.Procname.Hash.add cache callee_pname callee_summary_option ;
-      callee_summary_option
+    match LocalCache.get callee_pname with
+    | Some callee_summary_option ->
+        callee_summary_option
+    | None ->
+        let callee_summary_option, update_memcached =
+          match memcache_get callee_pname with
+          | Some summ_opt ->
+              (summ_opt, false)
+          | None ->
+              if callee_should_be_analyzed callee then
+                match get_callee_proc_desc callee with
+                | Some callee_pdesc ->
+                    ( Some
+                        (run_proc_analysis
+                           ~caller_pdesc:(Option.map ~f:Summary.get_proc_desc caller_summary)
+                           callee_pdesc)
+                    , true )
+                | None ->
+                    (Summary.OnDisk.get callee_pname, true)
+              else (
+                EventLogger.log_skipped_pname (F.asprintf "%a" Typ.Procname.pp callee_pname) ;
+                (Summary.OnDisk.get callee_pname, true) )
+        in
+        if update_memcached then memcache_set callee_pname callee_summary_option ;
+        LocalCache.add callee_pname callee_summary_option ;
+        callee_summary_option
 
 
 let analyze_proc_desc ~caller_summary callee_pdesc =

infer/src/backend/ondemand.mli

@@ -27,11 +27,13 @@ val analyze_proc_name_no_caller : Typ.Procname.t -> Summary.t option
 val set_exe_env : Exe_env.t -> unit
 (** Set the execution enviroment used during on-demand analysis. *)
 
-val clear_cache : unit -> unit
-(** Empty the cache of ondemand results *)
+module LocalCache : sig
+  val clear : unit -> unit
+  (** Empty the cache of ondemand results *)
 
-val remove_from_cache : Typ.Procname.t -> unit
-(** Remove an element from the cache of ondemand results *)
+  val remove : Typ.Procname.t -> unit
+  (** Remove an element from the cache of ondemand results *)
+end
 
 val analyze_file : Exe_env.t -> SourceFile.t -> unit
 (** Invoke all the callbacks registered in {!Callbacks} on the given file. *)