From 727cc8ce6d7df10f36c942424afa219bfcdad843 Mon Sep 17 00:00:00 2001 From: Jules Villard Date: Tue, 30 Jun 2020 07:07:00 -0700 Subject: [PATCH] [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 | 39 ++++++++--- infer/src/backend/GCStats.ml | 110 ++++++++++++++++++++++++++++++ infer/src/backend/GCStats.mli | 34 +++++++++ infer/src/integration/Driver.ml | 17 +++-- 4 files changed, 184 insertions(+), 16 deletions(-) create mode 100644 infer/src/backend/GCStats.ml create mode 100644 infer/src/backend/GCStats.mli diff --git a/infer/src/backend/BackendStats.ml b/infer/src/backend/BackendStats.ml index 8f770e932..fd5c8b29b 100644 --- a/infer/src/backend/BackendStats.ml +++ b/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 +let reset () = + copy initial ~into:global_stats ; + global_stats.gc_stats <- Some (GCStats.get ~since:ProgramStart) + 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@[ %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 diff --git a/infer/src/backend/GCStats.ml b/infer/src/backend/GCStats.ml new file mode 100644 index 000000000..bb360f50d --- /dev/null +++ b/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 + "@[ 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 diff --git a/infer/src/backend/GCStats.mli b/infer/src/backend/GCStats.mli new file mode 100644 index 000000000..15f269882 --- /dev/null +++ b/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 diff --git a/infer/src/integration/Driver.ml b/infer/src/integration/Driver.ml index e46504b83..ad532e929 100644 --- a/infer/src/integration/Driver.ml +++ b/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