From d5c59743b78dddc83591a846fafccc70c54f215c Mon Sep 17 00:00:00 2001
From: Jules Villard <jul@fb.com>
Date: Wed, 19 Sep 2018 10:13:08 -0700
Subject: [PATCH] [callbacks] trace each checker's execution time

Summary: Use `PerfEvent` to record the execution time of individual checkers.

Reviewed By: jeremydubreil, mbouaziz

Differential Revision: D9832102

fbshipit-source-id: 678fca155
---
 infer/src/backend/callbacks.ml         | 26 ++++++++++++++++++--------
 infer/src/backend/callbacks.mli        |  5 +++--
 infer/src/checkers/registerCheckers.ml |  8 ++++----
 3 files changed, 25 insertions(+), 14 deletions(-)

diff --git a/infer/src/backend/callbacks.ml b/infer/src/backend/callbacks.ml
index 28438f049..1e157a16b 100644
--- a/infer/src/backend/callbacks.ml
+++ b/infer/src/backend/callbacks.ml
@@ -24,20 +24,22 @@ type cluster_callback_args =
 
 type cluster_callback_t = cluster_callback_args -> unit
 
-type procedure_callback = {dynamic_dispatch: bool; language: Language.t; callback: proc_callback_t}
+type procedure_callback =
+  {name: string; dynamic_dispatch: bool; language: Language.t; callback: proc_callback_t}
 
-type cluster_callback = {language: Language.t; callback: cluster_callback_t}
+type cluster_callback = {name: string; language: Language.t; callback: cluster_callback_t}
 
 let procedure_callbacks = ref []
 
 let cluster_callbacks = ref []
 
-let register_procedure_callback ?(dynamic_dispatch = false) language (callback : proc_callback_t) =
-  procedure_callbacks := {dynamic_dispatch; language; callback} :: !procedure_callbacks
+let register_procedure_callback ~name ?(dynamic_dispatch = false) language
+    (callback : proc_callback_t) =
+  procedure_callbacks := {name; dynamic_dispatch; language; callback} :: !procedure_callbacks
 
 
-let register_cluster_callback language (callback : cluster_callback_t) =
-  cluster_callbacks := {language; callback} :: !cluster_callbacks
+let register_cluster_callback ~name language (callback : cluster_callback_t) =
+  cluster_callbacks := {name; language; callback} :: !cluster_callbacks
 
 
 (** Collect what we need to know about a procedure for the analysis. *)
@@ -64,9 +66,17 @@ let iterate_procedure_callbacks exe_env summary proc_desc =
   let tenv = Exe_env.get_tenv exe_env proc_name in
   let is_specialized = Procdesc.is_specialized proc_desc in
   List.fold ~init:summary
-    ~f:(fun summary {dynamic_dispatch; language; callback} ->
+    ~f:(fun summary {name; dynamic_dispatch; language; callback} ->
       if Language.equal language procedure_language && (dynamic_dispatch || not is_specialized)
-      then callback {get_procs_in_file; tenv; summary; proc_desc; exe_env}
+      then (
+        PerfEvent.(
+          log (fun logger ->
+              log_begin_event logger ~name ~categories:["backend"]
+                ~arguments:[("proc", `String (Typ.Procname.to_string proc_name))]
+                () )) ;
+        let summary = callback {get_procs_in_file; tenv; summary; proc_desc; exe_env} in
+        PerfEvent.(log (fun logger -> log_end_event logger ())) ;
+        summary )
       else summary )
     !procedure_callbacks
 
diff --git a/infer/src/backend/callbacks.mli b/infer/src/backend/callbacks.mli
index 37aa0c992..b3d43cfc8 100644
--- a/infer/src/backend/callbacks.mli
+++ b/infer/src/backend/callbacks.mli
@@ -28,10 +28,11 @@ type cluster_callback_args =
 
 type cluster_callback_t = cluster_callback_args -> unit
 
-val register_procedure_callback : ?dynamic_dispatch:bool -> Language.t -> proc_callback_t -> unit
+val register_procedure_callback :
+  name:string -> ?dynamic_dispatch:bool -> Language.t -> proc_callback_t -> unit
 (** register a procedure callback *)
 
-val register_cluster_callback : Language.t -> cluster_callback_t -> unit
+val register_cluster_callback : name:string -> Language.t -> cluster_callback_t -> unit
 (** register a cluster callback *)
 
 val analyze_file : Exe_env.t -> SourceFile.t -> unit
diff --git a/infer/src/checkers/registerCheckers.ml b/infer/src/checkers/registerCheckers.ml
index 65f456ecb..1e46f6a18 100644
--- a/infer/src/checkers/registerCheckers.ml
+++ b/infer/src/checkers/registerCheckers.ml
@@ -124,15 +124,15 @@ let get_active_checkers () =
 
 
 let register checkers =
-  let register_one {callbacks} =
+  let register_one {name; callbacks} =
     let register_callback (callback, language) =
       match callback with
       | Procedure procedure_cb ->
-          Callbacks.register_procedure_callback language procedure_cb
+          Callbacks.register_procedure_callback ~name language procedure_cb
       | DynamicDispatch procedure_cb ->
-          Callbacks.register_procedure_callback ~dynamic_dispatch:true language procedure_cb
+          Callbacks.register_procedure_callback ~name ~dynamic_dispatch:true language procedure_cb
       | Cluster cluster_cb ->
-          Callbacks.register_cluster_callback language cluster_cb
+          Callbacks.register_cluster_callback ~name language cluster_cb
     in
     List.iter ~f:register_callback callbacks
   in