From 37720e1bbff119f4a0d7062984343b5c488ce5b8 Mon Sep 17 00:00:00 2001 From: Varun Arora Date: Thu, 8 Mar 2018 04:18:26 -0800 Subject: [PATCH] [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 | 10 ++-- infer/src/backend/InferPrint.ml | 5 +- infer/src/backend/PerfStats.ml | 84 ++++++++++++++++++++-------- infer/src/backend/PerfStats.mli | 2 +- infer/src/base/EventLogger.ml | 49 ++++++++++++++++ infer/src/base/EventLogger.mli | 21 +++++++ infer/src/clang/Capture.ml | 7 +-- infer/src/integration/Driver.ml | 6 +- infer/src/java/jMain.ml | 6 +- infer/src/opensource/JsonBuilder.ml | 2 +- infer/src/opensource/JsonBuilder.mli | 2 + 11 files changed, 151 insertions(+), 43 deletions(-) diff --git a/infer/src/backend/InferAnalyze.ml b/infer/src/backend/InferAnalyze.ml index 2a2bf2dcb..c23544158 100644 --- a/infer/src/backend/InferAnalyze.ml +++ b/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 diff --git a/infer/src/backend/InferPrint.ml b/infer/src/backend/InferPrint.ml index 052315f70..7b1200d2e 100644 --- a/infer/src/backend/InferPrint.ml +++ b/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 diff --git a/infer/src/backend/PerfStats.ml b/infer/src/backend/PerfStats.ml index 6c2cf850d..dc1ee7699 100644 --- a/infer/src/backend/PerfStats.ml +++ b/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) ) diff --git a/infer/src/backend/PerfStats.mli b/infer/src/backend/PerfStats.mli index 3529d6088..1aa07e06c 100644 --- a/infer/src/backend/PerfStats.mli +++ b/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. *) diff --git a/infer/src/base/EventLogger.ml b/infer/src/base/EventLogger.ml index f2ad846f1..3ec29ac0a 100644 --- a/infer/src/base/EventLogger.ml +++ b/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) -> diff --git a/infer/src/base/EventLogger.mli b/infer/src/base/EventLogger.mli index 3e723a128..a2300d548 100644 --- a/infer/src/base/EventLogger.mli +++ b/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 *) diff --git a/infer/src/clang/Capture.ml b/infer/src/clang/Capture.ml index 28e06dad0..2aca8ea3e 100644 --- a/infer/src/clang/Capture.ml +++ b/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 = diff --git a/infer/src/integration/Driver.ml b/infer/src/integration/Driver.ml index 13706d60c..5822e0f32 100644 --- a/infer/src/integration/Driver.ml +++ b/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 () = diff --git a/infer/src/java/jMain.ml b/infer/src/java/jMain.ml index 5269d117c..a5f1f1c9e 100644 --- a/infer/src/java/jMain.ml +++ b/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 = diff --git a/infer/src/opensource/JsonBuilder.ml b/infer/src/opensource/JsonBuilder.ml index 926ca805f..c9352b141 100644 --- a/infer/src/opensource/JsonBuilder.ml +++ b/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 diff --git a/infer/src/opensource/JsonBuilder.mli b/infer/src/opensource/JsonBuilder.mli index b5b84163a..5dc3739d2 100644 --- a/infer/src/opensource/JsonBuilder.mli +++ b/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