diff --git a/infer/src/backend/BackendStats.ml b/infer/src/backend/BackendStats.ml index 07d406b34..9565f4945 100644 --- a/infer/src/backend/BackendStats.ml +++ b/infer/src/backend/BackendStats.ml @@ -20,7 +20,9 @@ include struct ; mutable summary_has_model_queries: int ; mutable ondemand_procs_analyzed: int ; mutable ondemand_local_cache_hits: int - ; mutable ondemand_local_cache_misses: int } + ; mutable ondemand_local_cache_misses: int + ; mutable proc_locker_lock_sys_time: float + ; mutable proc_locker_unlock_sys_time: float } [@@deriving fields] end @@ -32,7 +34,9 @@ let global_stats = ; summary_has_model_queries= 0 ; ondemand_procs_analyzed= 0 ; ondemand_local_cache_hits= 0 - ; ondemand_local_cache_misses= 0 } + ; ondemand_local_cache_misses= 0 + ; proc_locker_lock_sys_time= 0. + ; proc_locker_unlock_sys_time= 0. } let get () = global_stats @@ -45,6 +49,14 @@ let incr field = set global_stats (Field.get field global_stats + 1) +let add field seconds_count = + match Field.setter field with + | None -> + L.die InternalError "add on non-mutable field %s" (Field.name field) + | Some set -> + set global_stats (Field.get field global_stats +. seconds_count) + + let incr_summary_file_try_load () = incr Fields.summary_file_try_load let incr_summary_read_from_disk () = incr Fields.summary_read_from_disk @@ -61,6 +73,14 @@ let incr_ondemand_local_cache_hits () = incr Fields.ondemand_local_cache_hits let incr_ondemand_local_cache_misses () = incr Fields.ondemand_local_cache_misses +let add_to_proc_locker_lock_sys_time seconds_count = + add Fields.proc_locker_lock_sys_time seconds_count + + +let add_to_proc_locker_unlock_sys_time seconds_count = + add Fields.proc_locker_unlock_sys_time seconds_count + + let copy from ~into : unit = let { summary_file_try_load ; summary_read_from_disk @@ -69,12 +89,15 @@ let copy from ~into : unit = ; summary_has_model_queries ; ondemand_procs_analyzed ; ondemand_local_cache_hits - ; ondemand_local_cache_misses } = + ; ondemand_local_cache_misses + ; proc_locker_lock_sys_time + ; proc_locker_unlock_sys_time } = from in Fields.Direct.set_all_mutable_fields into ~summary_file_try_load ~summary_read_from_disk ~summary_cache_hits ~summary_cache_misses ~summary_has_model_queries ~ondemand_procs_analyzed - ~ondemand_local_cache_hits ~ondemand_local_cache_misses + ~ondemand_local_cache_hits ~ondemand_local_cache_misses ~proc_locker_lock_sys_time + ~proc_locker_unlock_sys_time let merge stats1 stats2 = @@ -86,7 +109,10 @@ let merge stats1 stats2 = ; ondemand_procs_analyzed= stats1.ondemand_procs_analyzed + stats2.ondemand_procs_analyzed ; ondemand_local_cache_hits= stats1.ondemand_local_cache_hits + stats2.ondemand_local_cache_hits ; ondemand_local_cache_misses= - stats1.ondemand_local_cache_misses + stats2.ondemand_local_cache_misses } + stats1.ondemand_local_cache_misses + stats2.ondemand_local_cache_misses + ; proc_locker_lock_sys_time= stats1.proc_locker_lock_sys_time +. stats2.proc_locker_lock_sys_time + ; proc_locker_unlock_sys_time= + stats1.proc_locker_unlock_sys_time +. stats2.proc_locker_unlock_sys_time } let initial = @@ -97,7 +123,9 @@ let initial = ; summary_has_model_queries= 0 ; ondemand_procs_analyzed= 0 ; ondemand_local_cache_hits= 0 - ; ondemand_local_cache_misses= 0 } + ; ondemand_local_cache_misses= 0 + ; proc_locker_lock_sys_time= 0. + ; proc_locker_unlock_sys_time= 0. } let reset () = copy initial ~into:global_stats @@ -110,6 +138,9 @@ let pp f stats = let pp_int_field stats f field = F.fprintf f "%s= %d@;" (Field.name field) (Field.get field stats) in + let pp_float_field stats f field = + F.fprintf f "%s= %.8f@;" (Field.name field) (Field.get field stats) + in let pp_cache_hits stats cache_misses f cache_hits_field = let cache_hits = Field.get cache_hits_field stats in F.fprintf f "%s= %d (%t)@;" (Field.name cache_hits_field) cache_hits @@ -123,6 +154,8 @@ let pp f stats = ~ondemand_procs_analyzed:(pp_int_field stats f) ~ondemand_local_cache_hits:(pp_cache_hits stats stats.ondemand_local_cache_misses f) ~ondemand_local_cache_misses:(pp_int_field stats f) + ~proc_locker_lock_sys_time:(pp_float_field stats f) + ~proc_locker_unlock_sys_time:(pp_float_field stats f) in F.fprintf f "@[Backend stats:@\n@[ %t@]@]@." (pp_stats stats) @@ -131,10 +164,17 @@ let log_to_scuba stats = let create_counter field = LogEntry.mk_count ~label:("backend_stats." ^ Field.name field) ~value:(Field.get field stats) in + let create_float_counter field = + LogEntry.mk_count + ~label:("backend_stats." ^ Field.name field) + ~value:(Field.get field stats |> Int.of_float) + 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 ~summary_has_model_queries:create_counter ~ondemand_procs_analyzed:create_counter ~ondemand_local_cache_hits:create_counter ~ondemand_local_cache_misses:create_counter + ~proc_locker_lock_sys_time:create_float_counter + ~proc_locker_unlock_sys_time:create_float_counter in ScubaLogging.log_many entries diff --git a/infer/src/backend/BackendStats.mli b/infer/src/backend/BackendStats.mli index 2a5e25926..5eab4f877 100644 --- a/infer/src/backend/BackendStats.mli +++ b/infer/src/backend/BackendStats.mli @@ -31,6 +31,10 @@ val incr_ondemand_local_cache_hits : unit -> unit val incr_ondemand_local_cache_misses : unit -> unit +val add_to_proc_locker_lock_sys_time : float -> unit + +val add_to_proc_locker_unlock_sys_time : float -> unit + val reset : unit -> unit (** reset all stats *) diff --git a/infer/src/backend/ProcLocker.ml b/infer/src/backend/ProcLocker.ml index a59b4eb42..fa2c1efb3 100644 --- a/infer/src/backend/ProcLocker.ml +++ b/infer/src/backend/ProcLocker.ml @@ -9,6 +9,18 @@ open! IStd exception UnlockNotLocked of Procname.t +let log_lock_systime = BackendStats.add_to_proc_locker_lock_sys_time + +let log_unlock_systime = BackendStats.add_to_proc_locker_unlock_sys_time + +let record_sys_time_of ~f ~log_f = + let start_time = Unix.times () in + let result = f () in + let end_time = Unix.times () in + let sys_time_spent = end_time.tms_stime -. start_time.tms_stime in + log_f sys_time_spent ; result + + let locks_dir = Config.procnames_locks_dir let setup () = Utils.rmtree locks_dir ; Utils.create_dir locks_dir @@ -18,12 +30,14 @@ let clean () = () let filename_from pname = locks_dir ^/ Procname.to_filename pname let unlock pname = - try Unix.unlink (filename_from pname) - with Unix.Unix_error (Unix.ENOENT, _, _) -> raise (UnlockNotLocked pname) + record_sys_time_of ~log_f:log_unlock_systime ~f:(fun () -> + try Unix.unlink (filename_from pname) + with Unix.Unix_error (Unix.ENOENT, _, _) -> raise (UnlockNotLocked pname) ) let try_lock pname = - try - Unix.openfile ~mode:[O_CREAT; O_EXCL; O_RDONLY] (filename_from pname) |> Unix.close ; - true - with Unix.Unix_error (Unix.EEXIST, _, _) -> false + record_sys_time_of ~log_f:log_lock_systime ~f:(fun () -> + try + Unix.openfile ~mode:[O_CREAT; O_EXCL; O_RDONLY] (filename_from pname) |> Unix.close ; + true + with Unix.Unix_error (Unix.EEXIST, _, _) -> false )