From c2a53a1334f889ec7ef39a9848e086076dd51e12 Mon Sep 17 00:00:00 2001 From: Fernando Gasperi Jabalera Date: Wed, 26 Feb 2020 04:18:42 -0800 Subject: [PATCH] [scheduler] Add wall time to ExecutionDuration Summary: Add the wall time to the ExecutionDuration. If this is not included we are not considering off-cpu time. Reviewed By: ngorogiannis Differential Revision: D20099667 fbshipit-source-id: 49dbfd739 --- infer/src/backend/BackendStats.ml | 5 +++- infer/src/backend/ExecutionDuration.ml | 35 ++++++++++++++++--------- infer/src/backend/ExecutionDuration.mli | 10 +++++-- infer/src/backend/RestartScheduler.ml | 9 ++++--- 4 files changed, 39 insertions(+), 20 deletions(-) diff --git a/infer/src/backend/BackendStats.ml b/infer/src/backend/BackendStats.ml index aa9815cf5..f3af9df08 100644 --- a/infer/src/backend/BackendStats.ml +++ b/infer/src/backend/BackendStats.ml @@ -195,7 +195,10 @@ let log_to_scuba stats = ~duration_ms:(ExecutionDuration.sys_time field_value |> secs_to_ms) ; LogEntry.mk_time ~label:("backend_stats." ^ Field.name field ^ "_user") - ~duration_ms:(ExecutionDuration.user_time field_value |> secs_to_ms) ] + ~duration_ms:(ExecutionDuration.user_time field_value |> secs_to_ms) + ; LogEntry.mk_time + ~label:("backend_stats." ^ Field.name field ^ "_wall") + ~duration_ms:(ExecutionDuration.wall_time field_value |> secs_to_ms) ] in let entries = Fields.to_list ~summary_file_try_load:create_counter ~summary_read_from_disk:create_counter diff --git a/infer/src/backend/ExecutionDuration.ml b/infer/src/backend/ExecutionDuration.ml index 565209464..0e9944cd9 100644 --- a/infer/src/backend/ExecutionDuration.ml +++ b/infer/src/backend/ExecutionDuration.ml @@ -30,34 +30,43 @@ module Duration = struct let secs d = d.time +. d.comp end -type t = {utime: Duration.t; stime: Duration.t} +type t = {user: Duration.t; sys: Duration.t; wall: Mtime.Span.t} + +type counter = {process_times: Unix.process_times; wall_time: Mtime_clock.counter} type 'a evaluation_result = {result: 'a; execution_duration: t} -let zero = {utime= Duration.zero; stime= Duration.zero} +let zero = {user= Duration.zero; sys= Duration.zero; wall= Mtime.Span.zero} -let since (from : Unix.process_times) = +let since {process_times; wall_time} = let now = Unix.times () in - { utime= Duration.since from.tms_utime ~now:now.tms_utime - ; stime= Duration.since from.tms_stime ~now:now.tms_stime } + { user= Duration.since process_times.tms_utime ~now:now.tms_utime + ; sys= Duration.since process_times.tms_stime ~now:now.tms_stime + ; wall= Mtime_clock.count wall_time } let add exe_d1 exe_d2 = - {utime= Duration.add exe_d1.utime exe_d2.utime; stime= Duration.add exe_d1.stime exe_d2.stime} + { user= Duration.add exe_d1.user exe_d2.user + ; sys= Duration.add exe_d1.sys exe_d2.sys + ; wall= Mtime.Span.add exe_d1.wall exe_d2.wall } + +let add_duration_since exe_duration from = add exe_duration (since from) -let add_duration_since exe_duration (from : Unix.process_times) = add exe_duration (since from) +let user_time exe_duration = Duration.secs exe_duration.user -let user_time exe_duration = Duration.secs exe_duration.utime +let sys_time exe_duration = Duration.secs exe_duration.sys -let sys_time exe_duration = Duration.secs exe_duration.stime +let wall_time exe_duration = Mtime.Span.to_s exe_duration.wall let pp ~field fmt exe_duration = - F.fprintf fmt "%s_utime= %.8f@;%s_stime= %.8f" field (user_time exe_duration) field - (sys_time exe_duration) + F.fprintf fmt "%s_user= %.8f@;%s_sys= %.8f@;%s_wall= %.8f" field (user_time exe_duration) field + (sys_time exe_duration) field (wall_time exe_duration) + +let counter () = {process_times= Unix.times (); wall_time= Mtime_clock.counter ()} let timed_evaluate ~f = - let start_time = Unix.times () in + let start = counter () in let result = f () in - {result; execution_duration= since start_time} + {result; execution_duration= since start} diff --git a/infer/src/backend/ExecutionDuration.mli b/infer/src/backend/ExecutionDuration.mli index f6938b529..5a9467cd7 100644 --- a/infer/src/backend/ExecutionDuration.mli +++ b/infer/src/backend/ExecutionDuration.mli @@ -9,13 +9,17 @@ open! IStd type t +type counter + type 'a evaluation_result = {result: 'a; execution_duration: t} val zero : t -val since : Unix.process_times -> t +val counter : unit -> counter + +val since : counter -> t -val add_duration_since : t -> Unix.process_times -> t +val add_duration_since : t -> counter -> t val add : t -> t -> t @@ -23,6 +27,8 @@ val user_time : t -> float val sys_time : t -> float +val wall_time : t -> float + val pp : field:string -> Format.formatter -> t -> unit val timed_evaluate : f:(unit -> 'a) -> 'a evaluation_result diff --git a/infer/src/backend/RestartScheduler.ml b/infer/src/backend/RestartScheduler.ml index 9e9d46f35..1de82be57 100644 --- a/infer/src/backend/RestartScheduler.ml +++ b/infer/src/backend/RestartScheduler.ml @@ -54,15 +54,16 @@ let if_restart_scheduler f = type locked_proc = - {pname: Procname.t; start: Unix.process_times; mutable callees_useful: ExecutionDuration.t} + {pname: Procname.t; start: ExecutionDuration.counter; mutable callees_useful: ExecutionDuration.t} let locked_procs = Stack.create () let record_locked_proc (pname : Procname.t) = - Stack.push locked_procs {pname; start= Unix.times (); callees_useful= ExecutionDuration.zero} + Stack.push locked_procs + {pname; start= ExecutionDuration.counter (); callees_useful= ExecutionDuration.zero} -let add_to_useful_time (from : Unix.process_times) = +let add_to_useful_time from = BackendStats.add_to_restart_scheduler_useful_time (ExecutionDuration.since from) @@ -70,7 +71,7 @@ let add_to_useful_exe_duration exe_duration = BackendStats.add_to_restart_scheduler_useful_time exe_duration -let add_to_total_time (from : Unix.process_times) = +let add_to_total_time from = BackendStats.add_to_restart_scheduler_total_time (ExecutionDuration.since from)