[logging] performance stats logging via EventLogger

Summary:
- New Event type in EventLogger: PerformanceStats
    - Contains some of the information logged to disk by PerfStats, as well as a `stats_type` tag to indicate which type of process the stats are from
- PerfStats.register_report_at_exit now takes 3 string arguments and constructs the file path and determines stats_type based off of them
    - Changed all clients of PerfStats to use new api

Reviewed By: dulmarod

Differential Revision: D7131904

fbshipit-source-id: 9226b5d

infer/src/backend/InferAnalyze.ml

@@ -156,8 +156,8 @@ let main ~changed_files ~makefile =
 
 
 let register_perf_stats_report () =
-  let stats_dir = Filename.concat Config.results_dir Config.backend_stats_dir_name in
-  let cluster = match Config.cluster_cmdline with Some cl -> "_" ^ cl | None -> "" in
-  let stats_base = Config.perf_stats_prefix ^ Filename.basename cluster ^ ".json" in
-  let stats_file = Filename.concat stats_dir stats_base in
-  PerfStats.register_report_at_exit stats_file
+  let cluster =
+    match Config.cluster_cmdline with Some cl -> "_" ^ Filename.basename cl | None -> ""
+  in
+  let filename = F.sprintf "%s%s.json" Config.perf_stats_prefix cluster in
+  PerfStats.register_report_at_exit filename Config.backend_stats_dir_name

infer/src/backend/InferPrint.ml

@@ -867,9 +867,8 @@ let get_summary_iterator () =
 
 
 let register_perf_stats_report () =
-  let stats_dir = Filename.concat Config.results_dir Config.reporting_stats_dir_name in
-  let stats_file = Filename.concat stats_dir (Config.perf_stats_prefix ^ ".json") in
-  PerfStats.register_report_at_exit stats_file
+  let filename = F.sprintf "%s.json" Config.perf_stats_prefix in
+  PerfStats.register_report_at_exit filename Config.reporting_stats_dir_name
 
 
 (** Although the out_file is an Option type, the None option is strictly meant for the

infer/src/backend/PerfStats.ml

@@ -10,6 +10,7 @@
 (** Performance Statistics gathering and reporting *)
 
 open! IStd
+module F = Format
 module L = Logging
 
 type perf_stats =
@@ -102,34 +103,69 @@ let aggregate s =
     ; ("minor_heap_kb", StatisticsToolbox.to_json aggr_minor_heap_kb) ]
 
 
-let stats () =
-  let words_to_kb n = n *. float_of_int (Sys.word_size / 8) /. 1024. in
+let stats source_file stats_type =
+  let bytes_per_word = Sys.word_size / 8 in
+  let words_to_bytes n = n *. float_of_int bytes_per_word in
+  let words_to_kb n = words_to_bytes n /. 1024. in
   let words_to_mb n = words_to_kb n /. 1024. in
   let words_to_gb n = words_to_mb n /. 1024. in
   let gc_stats = Gc.quick_stat () in
   let allocated_words = gc_stats.minor_words +. gc_stats.major_words -. gc_stats.promoted_words in
   let gc_ctrl = Gc.get () in
   let exit_times = Unix.times () in
-  { rtime= Mtime_clock.elapsed () |> Mtime.Span.to_s
-  ; utime= exit_times.tms_utime -. Utils.initial_times.tms_utime
-  ; stime= exit_times.tms_stime -. Utils.initial_times.tms_stime
-  ; cutime= exit_times.tms_cutime -. Utils.initial_times.tms_cutime
-  ; cstime= exit_times.tms_cstime -. Utils.initial_times.tms_cstime
-  ; minor_gb= words_to_gb gc_stats.minor_words
-  ; promoted_gb= words_to_gb gc_stats.promoted_words
-  ; major_gb= words_to_gb gc_stats.major_words
-  ; allocated_gb= words_to_gb allocated_words
-  ; minor_collections= gc_stats.minor_collections
-  ; major_collections= gc_stats.major_collections
-  ; compactions= gc_stats.compactions
-  ; top_heap_gb= words_to_gb (float_of_int gc_stats.top_heap_words)
-  ; stack_kb= words_to_kb (float_of_int gc_stats.stack_size)
-  ; minor_heap_kb= words_to_kb (float_of_int gc_ctrl.minor_heap_size) }
+  let rtime = Mtime_clock.elapsed () |> Mtime.Span.to_s in
+  let utime = exit_times.tms_utime -. Utils.initial_times.tms_utime in
+  let stime = exit_times.tms_stime -. Utils.initial_times.tms_stime in
+  let cutime = exit_times.tms_cutime -. Utils.initial_times.tms_cutime in
+  let cstime = exit_times.tms_cstime -. Utils.initial_times.tms_cstime in
+  let stats =
+    { rtime
+    ; utime
+    ; stime
+    ; cutime
+    ; cstime
+    ; minor_gb= words_to_gb gc_stats.minor_words
+    ; promoted_gb= words_to_gb gc_stats.promoted_words
+    ; major_gb= words_to_gb gc_stats.major_words
+    ; allocated_gb= words_to_gb allocated_words
+    ; minor_collections= gc_stats.minor_collections
+    ; major_collections= gc_stats.major_collections
+    ; compactions= gc_stats.compactions
+    ; top_heap_gb= words_to_gb (float_of_int gc_stats.top_heap_words)
+    ; stack_kb= words_to_kb (float_of_int gc_stats.stack_size)
+    ; minor_heap_kb= words_to_kb (float_of_int gc_ctrl.minor_heap_size) }
+  in
+  (* We log number of bytes instead of a larger unit in EventLogger so the EventLogger output can
+    display in whatever format fits best *)
+  let stats_event =
+    EventLogger.PerformanceStats
+      { lang= Language.to_explicit_string !Language.curr_language
+      ; source_file
+      ; stats_type
+      ; real_time= rtime
+      ; user_time= utime
+      ; sys_time= stime
+      ; children_user_time= cutime
+      ; children_sys_time= cstime
+      ; minor_heap_mem= words_to_bytes gc_stats.minor_words
+      ; promoted_minor_heap_mem= words_to_bytes gc_stats.promoted_words
+      ; major_heap_mem= words_to_bytes gc_stats.major_words
+      ; total_allocated_mem= words_to_bytes allocated_words
+      ; minor_collections= gc_stats.minor_collections
+      ; major_collections= gc_stats.major_collections
+      ; heap_compactions= gc_stats.compactions
+      ; top_heap_size= gc_stats.top_heap_words * bytes_per_word
+      ; stack_size= gc_stats.stack_size * bytes_per_word
+      ; minor_heap_size= gc_ctrl.minor_heap_size * bytes_per_word }
+  in
+  (stats, stats_event)
 
 
-let report_at_exit file () =
+let report_at_exit file source_file stats_type () =
   try
-    let json_stats = to_json (stats ()) in
+    let stats, stats_event = stats source_file stats_type in
+    let json_stats = to_json stats in
+    EventLogger.log stats_event ;
     try
       Unix.mkdir_p (Filename.dirname file) ;
       (* the same report may be registered across different infer processes *)
@@ -146,10 +182,14 @@ let report_at_exit file () =
 
 
 let register_report_at_exit =
-  (* take care of not double-registering the same perf stat report *)
   let registered_files = String.Table.create ~size:4 () in
-  fun file ->
+  fun filename ?source_file dirname ->
+    let dir = Filename.concat Config.results_dir dirname in
+    let file = Filename.concat dir filename in
+    (* take care of not double-registering the same perf stat report *)
     if not (Hashtbl.mem registered_files file) then (
       String.Table.set registered_files ~key:file ~data:() ;
       if not Config.buck_cache_mode then
-        Epilogues.register ~f:(report_at_exit file) ("stats reporting in " ^ file) )
+        Epilogues.register
+          ~f:(report_at_exit file source_file dirname)
+          ("stats reporting in " ^ file) )

infer/src/backend/PerfStats.mli

@@ -17,6 +17,6 @@ val from_json : Yojson.Basic.json -> perf_stats
 
 val aggregate : perf_stats list -> Yojson.Basic.json
 
-val register_report_at_exit : string -> unit
+val register_report_at_exit : string -> ?source_file:SourceFile.t -> string -> unit
 (** Create performance report when the current process terminates. Automatically disabled when
     [Config.buck_cache_mode] is true. *)

infer/src/base/EventLogger.ml

@@ -184,6 +184,50 @@ let create_frontend_exception_row base record =
             ; string_of_int record.source_location_end.col ])
 
 
+type performance_stats =
+  { lang: string
+  ; source_file: SourceFile.t option
+  ; stats_type: string
+  ; real_time: float
+  ; user_time: float
+  ; sys_time: float
+  ; children_user_time: float
+  ; children_sys_time: float
+  ; minor_heap_mem: float
+  ; promoted_minor_heap_mem: float
+  ; major_heap_mem: float
+  ; total_allocated_mem: float
+  ; minor_collections: int
+  ; major_collections: int
+  ; heap_compactions: int
+  ; top_heap_size: int
+  ; stack_size: int
+  ; minor_heap_size: int }
+
+let create_performance_stats_row base record =
+  let open JsonBuilder in
+  base |> add_string ~key:"lang" ~data:record.lang
+  |> add_string_opt ~key:"source_file"
+       ~data:(Option.map ~f:SourceFile.to_rel_path record.source_file)
+  |> add_string ~key:"stats_type" ~data:record.stats_type
+  |> add_float ~key:"real_time" ~data:record.real_time
+  |> add_float ~key:"user_time" ~data:record.user_time
+  |> add_float ~key:"sys_time" ~data:record.sys_time
+  |> add_float ~key:"children_user_time" ~data:record.children_user_time
+  |> add_float ~key:"children_sys_time" ~data:record.children_sys_time
+  |> add_float ~key:"minor_heap_mem" ~data:record.minor_heap_mem
+  |> add_float ~key:"promoted_minor_heap_mem" ~data:record.promoted_minor_heap_mem
+  |> add_float ~key:"major_heap_mem" ~data:record.major_heap_mem
+  |> add_float ~key:"total_allocated_mem" ~data:record.total_allocated_mem
+  |> add_int ~key:"minor_collections" ~data:record.minor_collections
+  |> add_int ~key:"major_collections" ~data:record.major_collections
+  |> add_int ~key:"heap_compactions" ~data:record.heap_compactions
+  |> add_int ~key:"top_heap_size" ~data:record.top_heap_size
+  |> add_int ~key:"stack_size" ~data:record.stack_size
+  |> add_int ~key:"minor_heap_size" ~data:record.minor_heap_size
+  |> add_string ~key:"stats_type" ~data:record.stats_type
+
+
 type procedures_translated =
   { lang: string
   ; procedures_translated_failed: int
@@ -203,6 +247,7 @@ type event =
   | AnalysisStats of analysis_stats
   | CallTrace of call_trace
   | FrontendException of frontend_exception
+  | PerformanceStats of performance_stats
   | ProceduresTranslatedSummary of procedures_translated
   | UncaughtException of exn * int
 
@@ -216,6 +261,8 @@ let string_of_event event =
       "CallTrace"
   | FrontendException _ ->
       "FrontendException"
+  | PerformanceStats _ ->
+      "PerformanceStats"
   | ProceduresTranslatedSummary _ ->
       "ProceduresTranslatedSummary"
   | UncaughtException _ ->
@@ -271,6 +318,8 @@ module LoggerImpl : S = struct
         create_call_trace_row base record
     | FrontendException record ->
         create_frontend_exception_row base record
+    | PerformanceStats record ->
+        create_performance_stats_row base record
     | ProceduresTranslatedSummary record ->
         create_procedures_translated_row base record
     | UncaughtException (exn, exitcode) ->

infer/src/base/EventLogger.mli

@@ -43,6 +43,26 @@ type frontend_exception =
   ; source_location_start: Location.t
   ; source_location_end: Location.t }
 
+type performance_stats =
+  { lang: string
+  ; source_file: SourceFile.t option
+  ; stats_type: string
+  ; real_time: float
+  ; user_time: float
+  ; sys_time: float
+  ; children_user_time: float
+  ; children_sys_time: float
+  ; minor_heap_mem: float
+  ; promoted_minor_heap_mem: float
+  ; major_heap_mem: float
+  ; total_allocated_mem: float
+  ; minor_collections: int
+  ; major_collections: int
+  ; heap_compactions: int
+  ; top_heap_size: int
+  ; stack_size: int
+  ; minor_heap_size: int }
+
 type procedures_translated =
   { lang: string
   ; procedures_translated_failed: int
@@ -54,6 +74,7 @@ type event =
   | AnalysisStats of analysis_stats
   | CallTrace of call_trace
   | FrontendException of frontend_exception
+  | PerformanceStats of performance_stats
   | ProceduresTranslatedSummary of procedures_translated
   | UncaughtException of exn * int  (** exception, exitcode *)
 

infer/src/clang/Capture.ml

@@ -8,6 +8,7 @@
  *)
 open! IStd
 module CLOpt = CommandLineOption
+module F = Format
 module L = Logging
 
 (** enable debug mode (to get more data saved to disk for future inspections) *)
@@ -24,11 +25,9 @@ let validate_decl_from_channel chan =
 
 
 let register_perf_stats_report source_file =
-  let stats_dir = Filename.concat Config.results_dir Config.frontend_stats_dir_name in
   let abbrev_source_file = DB.source_file_encoding source_file in
-  let stats_file = Config.perf_stats_prefix ^ "_" ^ abbrev_source_file ^ ".json" in
-  Unix.mkdir_p stats_dir ;
-  PerfStats.register_report_at_exit (Filename.concat stats_dir stats_file)
+  let filename = F.sprintf "%s_%s.json" Config.perf_stats_prefix abbrev_source_file in
+  PerfStats.register_report_at_exit filename ~source_file Config.frontend_stats_dir_name
 
 
 let init_global_state_for_capture_and_linters source_file =

infer/src/integration/Driver.ml

@@ -127,10 +127,8 @@ let clean_results_dir () =
 
 
 let register_perf_stats_report () =
-  let stats_dir = Filename.concat Config.results_dir Config.backend_stats_dir_name in
-  let stats_base = Config.perf_stats_prefix ^ ".json" in
-  let stats_file = Filename.concat stats_dir stats_base in
-  PerfStats.register_report_at_exit stats_file
+  let filename = F.sprintf "%s.json" Config.perf_stats_prefix in
+  PerfStats.register_report_at_exit filename Config.backend_stats_dir_name
 
 
 let reset_duplicates_file () =

infer/src/java/jMain.ml

@@ -11,13 +11,13 @@
 open! IStd
 open! PVariant
 open Javalib_pack
+module F = Format
 module L = Logging
 
 let register_perf_stats_report source_file =
-  let stats_dir = Filename.concat Config.results_dir Config.frontend_stats_dir_name in
   let abbrev_source_file = DB.source_file_encoding source_file in
-  let stats_file = Config.perf_stats_prefix ^ "_" ^ abbrev_source_file ^ ".json" in
-  PerfStats.register_report_at_exit (Filename.concat stats_dir stats_file)
+  let filename = F.sprintf "%s_%s.json" Config.perf_stats_prefix abbrev_source_file in
+  PerfStats.register_report_at_exit filename ~source_file Config.frontend_stats_dir_name
 
 
 let init_global_state source_file =

infer/src/opensource/JsonBuilder.ml

@@ -15,7 +15,7 @@ let empty = []
 
 let add_int t ~key ~data = (key, `Int data) :: t
 
-let _add_float t ~key ~data = (key, `Float data) :: t
+let add_float t ~key ~data = (key, `Float data) :: t
 
 let add_string t ~key ~data = (key, `String data) :: t
 

infer/src/opensource/JsonBuilder.mli

@@ -13,6 +13,8 @@ val empty : t
 
 val add_int : t -> key:string -> data:int -> t
 
+val add_float : t -> key:string -> data:float -> t
+
 val add_string : t -> key:string -> data:string -> t
 
 val add_string_opt : t -> key:string -> data:string option -> t