[reporting][perf] Add PerfStats support for reporting time and memory related stats separately

Summary:
- PerfStats can now report either time and/or memory stats, by default reporting both
- This is in preparation for adding just time or memory related logging in the future

Reviewed By: mbouaziz, dulmarod

Differential Revision: D7324556

fbshipit-source-id: e265b12
master
Varun Arora 7 years ago committed by Facebook Github Bot
parent 5014e7d9eb
commit fba4014d1c

@ -13,13 +13,8 @@ open! IStd
module F = Format
module L = Logging
type perf_stats =
{ rtime: float
; utime: float
; stime: float
; cutime: float
; cstime: float
; minor_gb: float
type mem_perf =
{ minor_gb: float
; promoted_gb: float
; major_gb: float
; allocated_gb: float
@ -30,6 +25,10 @@ type perf_stats =
; stack_kb: float
; minor_heap_kb: float }
type time_perf = {rtime: float; utime: float; stime: float; cutime: float; cstime: float}
type perf_stats = {mem: mem_perf option; time: time_perf option}
type stats_type =
| ClangLinters
| ClangFrontend
@ -79,79 +78,119 @@ let string_of_stats_type = function
let to_json ps =
`Assoc
[ ("rtime", `Float ps.rtime)
; ("utime", `Float ps.utime)
; ("stime", `Float ps.stime)
; ("cutime", `Float ps.cutime)
; ("cstime", `Float ps.cstime)
; ("minor_gb", `Float ps.minor_gb)
; ("promoted_gb", `Float ps.promoted_gb)
; ("major_gb", `Float ps.major_gb)
; ("allocated_gb", `Float ps.allocated_gb)
; ("minor_collections", `Int ps.minor_collections)
; ("major_collections", `Int ps.major_collections)
; ("compactions", `Int ps.compactions)
; ("top_heap_gb", `Float ps.top_heap_gb)
; ("stack_kb", `Float ps.stack_kb)
; ("minor_heap_kb", `Float ps.minor_heap_kb) ]
let time =
Option.value_map ~default:[] ps.time ~f:(fun time_perf ->
[ ( "time"
, `Assoc
[ ("rtime", `Float time_perf.rtime)
; ("utime", `Float time_perf.utime)
; ("stime", `Float time_perf.stime)
; ("cutime", `Float time_perf.cutime)
; ("cstime", `Float time_perf.cstime) ] ) ] )
in
let mem =
Option.value_map ~default:[] ps.mem ~f:(fun mem_perf ->
[ ( "mem"
, `Assoc
[ ("minor_gb", `Float mem_perf.minor_gb)
; ("promoted_gb", `Float mem_perf.promoted_gb)
; ("major_gb", `Float mem_perf.major_gb)
; ("allocated_gb", `Float mem_perf.allocated_gb)
; ("minor_collections", `Int mem_perf.minor_collections)
; ("major_collections", `Int mem_perf.major_collections)
; ("compactions", `Int mem_perf.compactions)
; ("top_heap_gb", `Float mem_perf.top_heap_gb)
; ("stack_kb", `Float mem_perf.stack_kb)
; ("minor_heap_kb", `Float mem_perf.minor_heap_kb) ] ) ] )
in
`Assoc (time @ mem)
let from_json json =
let open! Yojson.Basic.Util in
{ rtime= json |> member "rtime" |> to_float
; utime= json |> member "utime" |> to_float
; stime= json |> member "stime" |> to_float
; cutime= json |> member "cutime" |> to_float
; cstime= json |> member "cstime" |> to_float
; minor_gb= json |> member "minor_gb" |> to_float
; promoted_gb= json |> member "promoted_gb" |> to_float
; major_gb= json |> member "major_gb" |> to_float
; allocated_gb= json |> member "allocated_gb" |> to_float
; minor_collections= json |> member "minor_collections" |> to_int
; major_collections= json |> member "major_collections" |> to_int
; compactions= json |> member "compactions" |> to_int
; top_heap_gb= json |> member "top_heap_gb" |> to_float
; stack_kb= json |> member "stack_kb" |> to_float
; minor_heap_kb= json |> member "minor_heap_kb" |> to_float }
let mem =
json |> member "mem"
|> to_option (fun mem_perf ->
{ minor_gb= mem_perf |> member "minor_gb" |> to_float
; promoted_gb= mem_perf |> member "promoted_gb" |> to_float
; major_gb= mem_perf |> member "major_gb" |> to_float
; allocated_gb= mem_perf |> member "allocated_gb" |> to_float
; minor_collections= mem_perf |> member "minor_collections" |> to_int
; major_collections= mem_perf |> member "major_collections" |> to_int
; compactions= mem_perf |> member "compactions" |> to_int
; top_heap_gb= mem_perf |> member "top_heap_gb" |> to_float
; stack_kb= mem_perf |> member "stack_kb" |> to_float
; minor_heap_kb= mem_perf |> member "minor_heap_kb" |> to_float } )
in
let time =
json |> member "time"
|> to_option (fun time_perf ->
{ rtime= time_perf |> member "rtime" |> to_float
; utime= time_perf |> member "utime" |> to_float
; stime= time_perf |> member "stime" |> to_float
; cutime= time_perf |> member "cutime" |> to_float
; cstime= time_perf |> member "cstime" |> to_float } )
in
{mem; time}
let aggregate_mem_stats s =
let mk_stats f =
StatisticsToolbox.compute_statistics
(List.filter_map s ~f:(fun stats -> Option.map stats.mem ~f))
in
let aggr_minor_gb = mk_stats (fun mem_perf -> mem_perf.minor_gb) in
let aggr_promoted_gb = mk_stats (fun mem_perf -> mem_perf.promoted_gb) in
let aggr_major_gb = mk_stats (fun mem_perf -> mem_perf.major_gb) in
let aggr_allocated_gb = mk_stats (fun mem_perf -> mem_perf.allocated_gb) in
let aggr_minor_collections = mk_stats (fun mem -> float_of_int mem.minor_collections) in
let aggr_major_collections = mk_stats (fun mem -> float_of_int mem.major_collections) in
let aggr_compactions = mk_stats (fun mem -> float_of_int mem.compactions) in
let aggr_top_heap_gb = mk_stats (fun mem -> mem.top_heap_gb) in
let aggr_stack_kb = mk_stats (fun mem -> mem.stack_kb) in
let aggr_minor_heap_kb = mk_stats (fun mem -> mem.minor_heap_kb) in
[ ("minor_gb", aggr_minor_gb)
; ("promoted_gb", aggr_promoted_gb)
; ("major_gb", aggr_major_gb)
; ("allocated_gb", aggr_allocated_gb)
; ("minor_collections", aggr_minor_collections)
; ("major_collections", aggr_major_collections)
; ("compactions", aggr_compactions)
; ("top_heap_gb", aggr_top_heap_gb)
; ("stack_kb", aggr_stack_kb)
; ("minor_heap_kb", aggr_minor_heap_kb) ]
let aggregate_time_stats s =
let mk_stats f =
StatisticsToolbox.compute_statistics
(List.filter_map s ~f:(fun stats -> Option.map stats.time ~f))
in
let aggr_rtime = mk_stats (fun time -> time.rtime) in
let aggr_utime = mk_stats (fun time -> time.utime) in
let aggr_stime = mk_stats (fun time -> time.stime) in
let aggr_cutime = mk_stats (fun time -> time.cutime) in
let aggr_cstime = mk_stats (fun time -> time.cstime) in
[ ("rtime", aggr_rtime)
; ("utime", aggr_utime)
; ("stime", aggr_stime)
; ("cutime", aggr_cutime)
; ("cstime", aggr_cstime) ]
let aggregate s =
let mk_stats f = StatisticsToolbox.compute_statistics (List.map ~f s) in
let aggr_rtime = mk_stats (fun stats -> stats.rtime) in
let aggr_utime = mk_stats (fun stats -> stats.utime) in
let aggr_stime = mk_stats (fun stats -> stats.stime) in
let aggr_cutime = mk_stats (fun stats -> stats.cutime) in
let aggr_cstime = mk_stats (fun stats -> stats.cstime) in
let aggr_minor_gb = mk_stats (fun stats -> stats.minor_gb) in
let aggr_promoted_gb = mk_stats (fun stats -> stats.promoted_gb) in
let aggr_major_gb = mk_stats (fun stats -> stats.major_gb) in
let aggr_allocated_gb = mk_stats (fun stats -> stats.allocated_gb) in
let aggr_minor_collections = mk_stats (fun stats -> float_of_int stats.minor_collections) in
let aggr_major_collections = mk_stats (fun stats -> float_of_int stats.major_collections) in
let aggr_compactions = mk_stats (fun stats -> float_of_int stats.compactions) in
let aggr_top_heap_gb = mk_stats (fun stats -> stats.top_heap_gb) in
let aggr_stack_kb = mk_stats (fun stats -> stats.stack_kb) in
let aggr_minor_heap_kb = mk_stats (fun stats -> stats.minor_heap_kb) in
`Assoc
[ ("rtime", StatisticsToolbox.to_json aggr_rtime)
; ("utime", StatisticsToolbox.to_json aggr_utime)
; ("stime", StatisticsToolbox.to_json aggr_stime)
; ("cutime", StatisticsToolbox.to_json aggr_cutime)
; ("cstime", StatisticsToolbox.to_json aggr_cstime)
; ("minor_gb", StatisticsToolbox.to_json aggr_minor_gb)
; ("promoted_gb", StatisticsToolbox.to_json aggr_promoted_gb)
; ("major_gb", StatisticsToolbox.to_json aggr_major_gb)
; ("allocated_gb", StatisticsToolbox.to_json aggr_allocated_gb)
; ("minor_collections", StatisticsToolbox.to_json aggr_minor_collections)
; ("major_collections", StatisticsToolbox.to_json aggr_major_collections)
; ("compactions", StatisticsToolbox.to_json aggr_compactions)
; ("top_heap_gb", StatisticsToolbox.to_json aggr_top_heap_gb)
; ("stack_kb", StatisticsToolbox.to_json aggr_stack_kb)
; ("minor_heap_kb", StatisticsToolbox.to_json aggr_minor_heap_kb) ]
let stats source_file stats_type =
let build_json_list =
List.fold_right ~init:[] ~f:(fun (key, stats) l ->
match stats with Some stats -> (key, StatisticsToolbox.to_json stats) :: l | None -> l )
in
let mem_stats = build_json_list (aggregate_mem_stats s) in
let time_stats = build_json_list (aggregate_time_stats s) in
let mem_json = if List.is_empty mem_stats then [] else [("mem", `Assoc mem_stats)] in
let time_json = if List.is_empty time_stats then [] else [("time", `Assoc time_stats)] in
`Assoc (time_json @ mem_json)
let compute_mem_stats () =
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
@ -160,42 +199,24 @@ let stats source_file stats_type =
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
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) }
Some
{ 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= string_of_stats_type 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
let mem =
Some
{ EventLogger.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
@ -206,12 +227,46 @@ let stats source_file stats_type =
; stack_size= gc_stats.stack_size * bytes_per_word
; minor_heap_size= gc_ctrl.minor_heap_size * bytes_per_word }
in
(stats, mem)
let compute_time_stats () =
let exit_times = Unix.times () in
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 = Some {rtime; utime; stime; cutime; cstime} in
let time =
Some
{ EventLogger.real_time= rtime
; user_time= utime
; sys_time= stime
; children_user_time= cutime
; children_sys_time= cstime }
in
(stats, time)
let compute_stats ?(include_mem= true) ?(include_time= true) source_file stats_type =
let mem, mem_perf = if include_mem then compute_mem_stats () else (None, None) in
let time, time_perf = if include_time then compute_time_stats () else (None, None) in
let stats = {mem; time} in
let stats_event =
EventLogger.PerformanceStats
{ lang= Language.to_explicit_string !Language.curr_language
; source_file
; stats_type= string_of_stats_type stats_type
; mem_perf
; time_perf }
in
(stats, stats_event)
let report file source_file stats_type () =
let report ?include_mem ?include_time file source_file stats_type () =
try
let stats, stats_event = stats source_file stats_type in
let stats, stats_event = compute_stats ?include_mem ?include_time source_file stats_type in
let json_stats = to_json stats in
EventLogger.log stats_event ;
(* We always log to EventLogger, but json files are unnecessary to log outside of developer mode *)
@ -233,20 +288,22 @@ let report file source_file stats_type () =
let registered_files = ref String.Set.empty
let handle_report filename ?source_file stats_type ~f =
let handle_report ?include_mem ?include_time filename ?source_file stats_type ~f =
let dirname = dirname_of_stats_type stats_type in
let relative_path = Filename.concat dirname filename in
let absolute_path = Filename.concat Config.results_dir relative_path in
(* make sure to not double register the same perf stat report *)
if not (String.Set.mem !registered_files relative_path) then (
registered_files := String.Set.add !registered_files relative_path ;
f (report absolute_path source_file stats_type) relative_path )
f (report ?include_mem ?include_time absolute_path source_file stats_type) relative_path )
let report_now filename ?source_file stats_type =
handle_report filename ?source_file stats_type ~f:(fun report _ -> report ())
let report_now ?include_mem ?include_time filename ?source_file stats_type =
handle_report ?include_mem ?include_time filename ?source_file stats_type ~f:(fun report _ ->
report () )
let register_report_at_exit filename ?source_file stats_type =
handle_report filename ?source_file stats_type ~f:(fun report relative_path ->
let register_report_at_exit ?include_mem ?include_time filename ?source_file stats_type =
handle_report ?include_mem ?include_time filename ?source_file stats_type ~f:
(fun report relative_path ->
Epilogues.register ~f:report ("stats reporting in " ^ relative_path) )

@ -27,8 +27,12 @@ val from_json : Yojson.Basic.json -> perf_stats
val aggregate : perf_stats list -> Yojson.Basic.json
val report_now : string -> ?source_file:SourceFile.t -> stats_type -> unit
val report_now :
?include_mem:bool -> ?include_time:bool -> string -> ?source_file:SourceFile.t -> stats_type
-> unit
(** Create performance report immediately *)
val register_report_at_exit : string -> ?source_file:SourceFile.t -> stats_type -> unit
val register_report_at_exit :
?include_mem:bool -> ?include_time:bool -> string -> ?source_file:SourceFile.t -> stats_type
-> unit
(** Create performance report when the current process terminates *)

@ -186,16 +186,8 @@ 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
type mem_perf =
{ minor_heap_mem: float
; promoted_minor_heap_mem: float
; major_heap_mem: float
; total_allocated_mem: float
@ -206,28 +198,47 @@ type performance_stats =
; stack_size: int
; minor_heap_size: int }
type time_perf =
{ real_time: float
; user_time: float
; sys_time: float
; children_user_time: float
; children_sys_time: float }
type performance_stats =
{ lang: string
; source_file: SourceFile.t option
; stats_type: string
; mem_perf: mem_perf option
; time_perf: time_perf option }
let create_performance_stats_row base record =
let open JsonBuilder in
let add_mem_perf t =
Option.value_map ~default:t record.mem_perf ~f:(fun mem_perf ->
t |> add_float ~key:"minor_heap_mem" ~data:mem_perf.minor_heap_mem
|> add_float ~key:"promoted_minor_heap_mem" ~data:mem_perf.promoted_minor_heap_mem
|> add_float ~key:"major_heap_mem" ~data:mem_perf.major_heap_mem
|> add_float ~key:"total_allocated_mem" ~data:mem_perf.total_allocated_mem
|> add_int ~key:"minor_collections" ~data:mem_perf.minor_collections
|> add_int ~key:"major_collections" ~data:mem_perf.major_collections
|> add_int ~key:"heap_compactions" ~data:mem_perf.heap_compactions
|> add_int ~key:"top_heap_size" ~data:mem_perf.top_heap_size
|> add_int ~key:"stack_size" ~data:mem_perf.stack_size
|> add_int ~key:"minor_heap_size" ~data:mem_perf.minor_heap_size )
in
let add_time_perf t =
Option.value_map ~default:t record.time_perf ~f:(fun time_perf ->
t |> add_float ~key:"real_time" ~data:time_perf.real_time
|> add_float ~key:"user_time" ~data:time_perf.user_time
|> add_float ~key:"sys_time" ~data:time_perf.sys_time
|> add_float ~key:"children_user_time" ~data:time_perf.children_user_time
|> add_float ~key:"children_sys_time" ~data:time_perf.children_sys_time )
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
|> add_string ~key:"stats_type" ~data:record.stats_type |> add_mem_perf |> add_time_perf
type procedures_translated =

@ -43,16 +43,8 @@ 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
type mem_perf =
{ minor_heap_mem: float
; promoted_minor_heap_mem: float
; major_heap_mem: float
; total_allocated_mem: float
@ -63,6 +55,20 @@ type performance_stats =
; stack_size: int
; minor_heap_size: int }
type time_perf =
{ real_time: float
; user_time: float
; sys_time: float
; children_user_time: float
; children_sys_time: float }
type performance_stats =
{ lang: string
; source_file: SourceFile.t option
; stats_type: string
; mem_perf: mem_perf option
; time_perf: time_perf option }
type procedures_translated =
{ lang: string
; procedures_translated_failed: int

@ -31,29 +31,34 @@ let to_json s =
let compute_statistics values =
let num_elements = List.length values in
let sum = List.fold ~f:(fun acc v -> acc +. v) ~init:0.0 values in
let average = sum /. float_of_int num_elements in
let values_arr = Array.of_list values in
Array.sort
~cmp:(fun a b -> if Float.equal a b then 0 else if a -. b < 0.0 then -1 else 1)
values_arr ;
let percentile pct =
assert (pct >= 0.0 && pct <= 1.0) ;
assert (num_elements > 0) ;
let max_index = num_elements - 1 in
let pct_index = float_of_int max_index *. pct in
let low_index = int_of_float (Pervasives.floor pct_index) in
let high_index = int_of_float (Pervasives.ceil pct_index) in
let low = values_arr.(low_index) in
let high = values_arr.(high_index) in
(low +. high) /. 2.0
in
{ sum
; avg= average
; min= percentile 0.0
; p10= percentile 0.10
; median= percentile 0.50
; p75= percentile 0.75
; max= percentile 1.0
; count= num_elements }
match values with
| [] ->
None
| _ :: _ as values ->
let num_elements = List.length values in
let sum = List.fold ~f:(fun acc v -> acc +. v) ~init:0.0 values in
let average = sum /. float_of_int num_elements in
let values_arr = Array.of_list values in
Array.sort
~cmp:(fun a b -> if Float.equal a b then 0 else if a -. b < 0.0 then -1 else 1)
values_arr ;
let percentile pct =
assert (pct >= 0.0 && pct <= 1.0) ;
assert (num_elements > 0) ;
let max_index = num_elements - 1 in
let pct_index = float_of_int max_index *. pct in
let low_index = int_of_float (Pervasives.floor pct_index) in
let high_index = int_of_float (Pervasives.ceil pct_index) in
let low = values_arr.(low_index) in
let high = values_arr.(high_index) in
(low +. high) /. 2.0
in
Some
{ sum
; avg= average
; min= percentile 0.0
; p10= percentile 0.10
; median= percentile 0.50
; p75= percentile 0.75
; max= percentile 1.0
; count= num_elements }

@ -13,4 +13,4 @@ type t
val to_json : t -> Yojson.Basic.json
val compute_statistics : float list -> t
val compute_statistics : float list -> t option

Loading…
Cancel
Save