[log] add mem usage statistics

Summary:
Log stats obtained via `Gc.stat ()` for various phases:
- capture (doesn't include child infer processes created by the build
  system)
- analysis
- worker processes of the analysis, aggregated
- reporting phase
- total GC stats for the main infer process

Reviewed By: jberdine

Differential Revision: D22140131

fbshipit-source-id: b0ee39559

infer/src/backend/BackendStats.ml

@@ -24,12 +24,11 @@ include struct
     ; mutable proc_locker_unlock_time: ExecutionDuration.t
     ; mutable restart_scheduler_useful_time: ExecutionDuration.t
     ; mutable restart_scheduler_total_time: ExecutionDuration.t
-    ; mutable scheduler_process_analysis_time: ExecutionDuration.t }
-  (* - scheduler_process_analysis_time.wall counts the wall time of the analysis
-     phase
-     - scheduler_process_analysis_time.(user|sys) counts the (user|sys) time
-     only of the scheduler_process
-  *)
+    ; mutable scheduler_process_analysis_time: ExecutionDuration.t
+          (** - [scheduler_process_analysis_time.wall] counts the wall time of the analysis phase
+              - [scheduler_process_analysis_time.(user|sys)] counts the [(user|sys)] time only of
+                the scheduler_process *)
+    ; mutable gc_stats: GCStats.t option }
   [@@deriving fields]
 end
 
@@ -45,7 +44,8 @@ let global_stats =
   ; proc_locker_unlock_time= ExecutionDuration.zero
   ; restart_scheduler_useful_time= ExecutionDuration.zero
   ; restart_scheduler_total_time= ExecutionDuration.zero
-  ; scheduler_process_analysis_time= ExecutionDuration.zero }
+  ; scheduler_process_analysis_time= ExecutionDuration.zero
+  ; gc_stats= None }
 
 
 let get () = global_stats
@@ -109,13 +109,15 @@ let copy from ~into : unit =
       ; proc_locker_unlock_time
       ; restart_scheduler_useful_time
       ; restart_scheduler_total_time
-      ; scheduler_process_analysis_time } =
+      ; scheduler_process_analysis_time
+      ; gc_stats } =
     from
   in
   Fields.Direct.set_all_mutable_fields into ~summary_file_try_load ~summary_read_from_disk
     ~summary_cache_hits ~summary_cache_misses ~ondemand_procs_analyzed ~ondemand_local_cache_hits
     ~ondemand_local_cache_misses ~proc_locker_lock_time ~proc_locker_unlock_time
     ~restart_scheduler_useful_time ~restart_scheduler_total_time ~scheduler_process_analysis_time
+    ~gc_stats
 
 
 let merge stats1 stats2 =
@@ -136,7 +138,8 @@ let merge stats1 stats2 =
         stats2.restart_scheduler_useful_time
   ; restart_scheduler_total_time=
       ExecutionDuration.add stats1.restart_scheduler_total_time stats2.restart_scheduler_total_time
-  ; scheduler_process_analysis_time= ExecutionDuration.zero }
+  ; scheduler_process_analysis_time= ExecutionDuration.zero
+  ; gc_stats= Option.merge stats1.gc_stats stats2.gc_stats ~f:GCStats.merge }
 
 
 let initial =
@@ -151,12 +154,21 @@ let initial =
   ; proc_locker_unlock_time= ExecutionDuration.zero
   ; restart_scheduler_useful_time= ExecutionDuration.zero
   ; restart_scheduler_total_time= ExecutionDuration.zero
-  ; scheduler_process_analysis_time= ExecutionDuration.zero }
+  ; scheduler_process_analysis_time= ExecutionDuration.zero
+  ; gc_stats= None }
+
 
+let reset () =
+  copy initial ~into:global_stats ;
+  global_stats.gc_stats <- Some (GCStats.get ~since:ProgramStart)
 
-let reset () = copy initial ~into:global_stats
 
 let pp f stats =
+  let pp_field pp_value stats f field =
+    let field_value = Field.get field stats in
+    let field_name = Field.name field in
+    F.fprintf f "%s = %a@;" field_name pp_value field_value
+  in
   let pp_hit_percent hit miss f =
     let total = hit + miss in
     if Int.equal total 0 then F.pp_print_string f "N/A%%" else F.fprintf f "%d%%" (hit * 100 / total)
@@ -186,6 +198,7 @@ let pp f stats =
       ~restart_scheduler_useful_time:(pp_execution_duration_field stats f)
       ~restart_scheduler_total_time:(pp_execution_duration_field stats f)
       ~scheduler_process_analysis_time:(pp_execution_duration_field stats f)
+      ~gc_stats:(pp_field (Pp.option GCStats.pp) stats f)
   in
   F.fprintf f "@[Backend stats:@\n@[<v2>  %t@]@]@." (pp_stats stats)
 
@@ -207,6 +220,9 @@ let log_to_scuba stats =
         ~label:("backend_stats." ^ Field.name field ^ "_wall")
         ~duration_ms:(ExecutionDuration.wall_time field_value |> secs_to_ms) ]
   in
+  let create_scuba_option scuba_creator field =
+    match Field.get field stats with None -> [] | Some value -> scuba_creator value
+  in
   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
@@ -215,6 +231,7 @@ let log_to_scuba stats =
       ~proc_locker_unlock_time:create_time_entry ~restart_scheduler_useful_time:create_time_entry
       ~restart_scheduler_total_time:create_time_entry
       ~scheduler_process_analysis_time:create_time_entry
+      ~gc_stats:(create_scuba_option (GCStats.to_scuba_entries ~prefix:"backend"))
     |> List.concat
   in
   ScubaLogging.log_many entries

infer/src/backend/GCStats.ml

@@ -0,0 +1,110 @@
+(*
+ * Copyright (c) Facebook, Inc. and its affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+module F = Format
+module L = Logging
+module Gc = Caml.Gc
+
+(** a subset of {!Gc.stat} that can be aggregated across multiple processes *)
+type t =
+  { minor_words: float
+  ; promoted_words: float
+  ; major_words: float
+  ; minor_collections: int
+  ; major_collections: int
+  ; compactions: int
+  ; max_top_heap_words: int  (** like [Gc.top_heap_words], aggregated with [max] *)
+  ; added_top_heap_words: int  (** like [Gc.top_heap_words], aggregated with [(+)] *) }
+
+type since = ProgramStart | PreviousStats of t
+
+let get ~since =
+  let stats = Gc.stat () in
+  match since with
+  | ProgramStart ->
+      { minor_words= stats.minor_words
+      ; promoted_words= stats.promoted_words
+      ; major_words= stats.major_words
+      ; minor_collections= stats.minor_collections
+      ; major_collections= stats.major_collections
+      ; compactions= stats.compactions
+      ; max_top_heap_words= stats.top_heap_words
+      ; added_top_heap_words= stats.top_heap_words }
+  | PreviousStats stats_prev ->
+      (* [top_heap_words] is going to be inaccurate if it was reached in the previous time period *)
+      { minor_words= stats.minor_words -. stats_prev.minor_words
+      ; promoted_words= stats.promoted_words -. stats_prev.promoted_words
+      ; major_words= stats.major_words -. stats_prev.major_words
+      ; minor_collections= stats.minor_collections - stats_prev.minor_collections
+      ; major_collections= stats.major_collections - stats_prev.major_collections
+      ; compactions= stats.compactions - stats_prev.compactions
+      ; max_top_heap_words= stats.top_heap_words
+      ; added_top_heap_words= stats.top_heap_words }
+
+
+let merge stats1 stats2 =
+  { minor_words= stats1.minor_words +. stats2.minor_words
+  ; promoted_words= stats1.promoted_words +. stats2.promoted_words
+  ; major_words= stats1.major_words +. stats2.major_words
+  ; minor_collections= stats1.minor_collections + stats2.minor_collections
+  ; major_collections= stats1.major_collections + stats2.major_collections
+  ; compactions= stats1.compactions + stats2.compactions
+  ; max_top_heap_words= max stats1.max_top_heap_words stats2.max_top_heap_words
+  ; added_top_heap_words= stats1.added_top_heap_words + stats2.added_top_heap_words }
+
+
+let pp f
+    ({ minor_words
+     ; promoted_words
+     ; major_words
+     ; minor_collections
+     ; major_collections
+     ; compactions
+     ; max_top_heap_words
+     ; added_top_heap_words }[@warning "+9"]) =
+  F.fprintf f
+    "@[<v2>  minor_words: %g@;\
+     promoted_words: %g@;\
+     major_words: %g@;\
+     minor_collections: %d@;\
+     major_collections: %d@;\
+     compactions: %d@;\
+     max top_heap_words: %d@;\
+     cumulative top_heap_words: %d@;\
+     @]"
+    minor_words promoted_words major_words minor_collections major_collections compactions
+    max_top_heap_words added_top_heap_words
+
+
+let to_scuba_entries ~prefix (stats : t) =
+  let create_counter field value =
+    LogEntry.mk_count ~label:(Printf.sprintf "%s_gc_stats.%s" prefix field) ~value
+  in
+  [ create_counter "minor_words" (Float.to_int stats.minor_words)
+  ; create_counter "promoted_words" (Float.to_int stats.promoted_words)
+  ; create_counter "major_words" (Float.to_int stats.major_words)
+  ; create_counter "minor_collections" stats.minor_collections
+  ; create_counter "major_collections" stats.major_collections
+  ; create_counter "compactions" stats.compactions
+  ; create_counter "max_top_heap_words" stats.max_top_heap_words
+  ; create_counter "added_top_heap_words" stats.added_top_heap_words ]
+
+
+let log_to_scuba ~prefix stats = ScubaLogging.log_many (to_scuba_entries ~prefix stats)
+
+let log ~name debug_kind stats =
+  L.debug debug_kind Quiet "@[GC stats for %s:@\n%a@]@." name pp stats ;
+  log_to_scuba ~prefix:name stats
+
+
+let log_f ~name debug_kind f =
+  let stats_before_f = get ~since:ProgramStart in
+  let r = f () in
+  let stats_f = get ~since:(PreviousStats stats_before_f) in
+  log ~name debug_kind stats_f ;
+  r

infer/src/backend/GCStats.mli

@@ -0,0 +1,34 @@
+(*
+ * Copyright (c) Facebook, Inc. and its affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+module F = Format
+module L = Logging
+
+type t
+
+val pp : F.formatter -> t -> unit
+
+val log : name:string -> L.debug_kind -> t -> unit
+(** log to infer's log file and to Scuba *)
+
+val log_f : name:string -> L.debug_kind -> (unit -> 'a) -> 'a
+(** log GC stats for the duration of the function passed as argument to infer's log file and to
+    Scuba *)
+
+type since =
+  | ProgramStart  (** get GC stats from the beginning of the program *)
+  | PreviousStats of t
+      (** get GC stats relative to another point in time where GC stats were obtained with
+          [get ~since:ProgramStart] *)
+
+val get : since:since -> t
+
+val merge : t -> t -> t
+(** combine statistics from two processes *)
+
+val to_scuba_entries : prefix:string -> t -> LogEntry.t list

infer/src/integration/Driver.ml

@@ -169,16 +169,18 @@ let capture ~changed_files = function
 
 (* shadowed for tracing *)
 let capture ~changed_files mode =
+  GCStats.log_f ~name:"capture" Capture
+  @@ fun () ->
+  ScubaLogging.execute_with_time_logging "capture"
+  @@ fun () ->
   PerfEvent.(log (fun logger -> log_begin_event logger ~name:"capture" ())) ;
   capture ~changed_files mode ;
   PerfEvent.(log (fun logger -> log_end_event logger ()))
 
 
-let capture ~changed_files mode =
-  ScubaLogging.execute_with_time_logging "capture" (fun () -> capture ~changed_files mode)
-
-
 let execute_analyze ~changed_files =
+  GCStats.log_f ~name:"analysis_scheduler" Analysis
+  @@ fun () ->
   PerfEvent.(log (fun logger -> log_begin_event logger ~name:"analyze" ())) ;
   InferAnalyze.main ~changed_files ;
   PerfEvent.(log (fun logger -> log_end_event logger ()))
@@ -208,6 +210,8 @@ let report ?(suppress_console = false) () =
 
 (* shadowed for tracing *)
 let report ?suppress_console () =
+  GCStats.log_f ~name:"report" Analysis
+  @@ fun () ->
   PerfEvent.(log (fun logger -> log_begin_event logger ~name:"report" ())) ;
   report ?suppress_console () ;
   PerfEvent.(log (fun logger -> log_end_event logger ()))
@@ -451,7 +455,10 @@ let run_epilogue () =
   ()
 
 
-let run_epilogue () = ScubaLogging.execute_with_time_logging "run_epilogue" run_epilogue
+let run_epilogue () =
+  GCStats.log ~name:"main_process_full" Analysis (GCStats.get ~since:ProgramStart) ;
+  ScubaLogging.execute_with_time_logging "run_epilogue" run_epilogue
+
 
 let read_config_changed_files () =
   match Config.changed_files_index with