pghs975uc
/
infer_clone
1
0
Fork 0
Code Issues Pull Requests Releases Wiki Activity

[reporting] add logging of call stats to backend

Browse Source 
Summary:
- During the symbolic execution stage of the backend, Infer will log detailed stats about procedure calls
- Logging is accomplished directly within symExec/Tabulation
- call_result type is moved to tabulation.ml

CallStats was a broken module that allocated a lot of useless memory. Now, Specs.CallStats and InferPrint.CallsCsv as well as the Calls report kind in InferPrint no longer exist.

Reviewed By: dulmarod

Differential Revision: D7016439

fbshipit-source-id: 40911ee
master
Varun Arora 7 years ago committed by Facebook Github Bot
parent 49e05217fe
commit e90eaeab49
10 changed files with 99 additions and 193 deletions
Show Stats Download Patch File Download Diff File

58
infer/src/backend/InferPrint.ml
Unescape View File

@ -380,24 +380,6 @@ let pp_text_of_report fmt report =
List.iter ~f:pp_row report ; F.fprintf fmt "@?"
module CallsCsv = struct
(** Write proc summary stats in csv format *)
let pp_calls fmt summary =
let pp x = F.fprintf fmt x in
let stats = summary.Specs.stats in
let caller_name = Specs.get_proc_name summary in
let do_call (callee_name, loc) trace =
pp "\"%s\"," (Escape.escape_csv (Typ.Procname.to_string caller_name)) ;
pp "\"%s\"," (Escape.escape_csv (Typ.Procname.to_filename caller_name)) ;
pp "\"%s\"," (Escape.escape_csv (Typ.Procname.to_string callee_name)) ;
pp "\"%s\"," (Escape.escape_csv (Typ.Procname.to_filename callee_name)) ;
pp "%s," (SourceFile.to_string (Specs.get_loc summary).Location.file) ;
pp "%d," loc.Location.line ;
pp "%a@\n" Specs.CallStats.pp_trace trace
in
Specs.CallStats.iter do_call stats.Specs.call_stats
end
module Stats = struct
type t =
{ files: (SourceFile.t, unit) Hashtbl.t
@ -643,7 +625,7 @@ let error_filter filters proc_name file error_desc error_name =
&& filters.Inferconfig.error_filter error_name && filters.Inferconfig.proc_filter proc_name
type report_kind = Issues | Procs | Stats | Calls | Summary [@@deriving compare]
type report_kind = Issues | Procs | Stats | Summary [@@deriving compare]
let _string_of_report_kind = function
| Issues ->
@ -652,8 +634,6 @@ let _string_of_report_kind = function
"Procs"
| Stats ->
"Stats"
| Calls ->
"Calls"
| Summary ->
"Summary"
@ -723,15 +703,6 @@ let pp_procs_in_format (format_kind, (outfile_opt: Utils.outfile option)) =
L.(die InternalError) "Printing procs in json/tests/text/logs is not implemented"
let pp_calls_in_format (format_kind, (outfile_opt: Utils.outfile option)) =
match format_kind with
| Csv ->
let outf = get_outfile outfile_opt in
CallsCsv.pp_calls outf.fmt
| Json | Tests | Text | Logs ->
L.(die InternalError) "Printing calls in json/tests/text is not implemented"
let pp_stats_in_format (format_kind, _) =
match format_kind with
| Csv ->
@ -766,14 +737,6 @@ let pp_procs summary procs_format_list =
List.iter ~f:pp_procs_in_format procs_format_list
let pp_calls summary calls_format_list =
let pp_calls_in_format format =
let pp_calls = pp_calls_in_format format in
pp_calls summary
in
List.iter ~f:pp_calls_in_format calls_format_list
let pp_stats error_filter linereader summary stats stats_format_list =
let pp_stats_in_format format =
let pp_stats = pp_stats_in_format format in
@ -795,8 +758,6 @@ let pp_summary_by_report_kind formats_by_report_kind summary error_filter linere
pp_procs summary format_list
| Stats, _ :: _ ->
pp_stats (error_filter file) linereader summary stats format_list
| Calls, _ :: _ ->
pp_calls summary format_list
| Summary, _ when InferCommand.equal Config.command Report && not Config.quiet ->
pp_summary summary
| _ ->
@ -927,8 +888,6 @@ let init_issues_format_list report_json =
let init_procs_format_list () = Option.value_map ~f:(mk_format Csv) ~default:[] Config.procs_csv
let init_calls_format_list () = Option.value_map ~f:(mk_format Csv) ~default:[] Config.calls_csv
let init_stats_format_list () =
let csv_format = Option.value_map ~f:(mk_format Csv) ~default:[] Config.stats_report in
let logs_format = if Config.log_events then [(Logs, None)] else [] in
@ -941,7 +900,7 @@ let init_files format_list_by_kind =
match (format_kind, report_kind) with
| Csv, Issues ->
L.(die InternalError) "Printing issues in a CSV format is not implemented"
| Logs, (Issues | Procs | Calls | Summary) ->
| Logs, (Issues | Procs | Summary) ->
L.(die InternalError) "Logging these reports is not implemented"
| Csv, Procs ->
let outfile = get_outfile outfile_opt in
@ -952,11 +911,7 @@ let init_files format_list_by_kind =
| Json, Issues ->
let outfile = get_outfile outfile_opt in
IssuesJson.pp_json_open outfile.fmt ()
| Csv, (Calls | Summary)
| Logs, Stats
| Json, (Procs | Stats | Calls | Summary)
| Tests, _
| Text, _ ->
| Csv, Summary | Logs, Stats | Json, (Procs | Stats | Summary) | Tests, _ | Text, _ ->
()
in
List.iter ~f:init_files_of_format format_list
@ -968,7 +923,7 @@ let finalize_and_close_files format_list_by_kind (stats: Stats.t) =
let close_files_of_report_kind (report_kind, format_list) =
let close_files_of_format (format_kind, (outfile_opt: Utils.outfile option)) =
( match (format_kind, report_kind) with
| Logs, (Issues | Procs | Calls | Summary) ->
| Logs, (Issues | Procs | Summary) ->
L.(die InternalError) "Logging these reports is not implemented"
| Csv, Stats ->
let outfile = get_outfile outfile_opt in
@ -976,9 +931,9 @@ let finalize_and_close_files format_list_by_kind (stats: Stats.t) =
| Json, Issues ->
let outfile = get_outfile outfile_opt in
IssuesJson.pp_json_close outfile.fmt ()
| Csv, (Issues | Procs | Calls | Summary)
| Csv, (Issues | Procs | Summary)
| Logs, Stats
| Json, (Procs | Stats | Calls | Summary)
| Json, (Procs | Stats | Summary)
| Tests, _
| Text, _ ->
() ) ;
@ -1019,7 +974,6 @@ let main ~report_json =
let formats_by_report_kind =
[ (Issues, issue_formats)
; (Procs, init_procs_format_list ())
; (Calls, init_calls_format_list ())
; (Stats, init_stats_format_list ())
; (Summary, []) ]
in

87
infer/src/backend/specs.ml
Unescape View File

@ -237,92 +237,13 @@ let spec_normalize = NormSpec.normalize
(** Cast a list of normalized specs to a list of specs *)
let normalized_specs_to_specs = NormSpec.tospecs
module CallStats = struct
(** module for tracing stats of function calls *)
module PnameLocHash = Hashtbl.Make (struct
type t = Typ.Procname.t * Location.t
let hash (pname, loc) = Hashtbl.hash (Typ.Procname.hash_pname pname, loc.Location.line)
let equal = [%compare.equal : Typ.Procname.t * Location.t]
end)
(** kind of result of a procedure call *)
type call_result =
| CR_success (** successful call *)
| CR_not_met (** precondition not met *)
| CR_not_found (** the callee has no specs *)
| CR_skip (** the callee was skipped *)
type trace = (call_result * bool) list
type t = trace PnameLocHash.t
let trace_add tr (res: call_result) in_footprint = (res, in_footprint) :: tr
let empty_trace : trace = []
let init calls =
let hash = PnameLocHash.create 1 in
let do_call pn_loc = PnameLocHash.add hash pn_loc empty_trace in
List.iter ~f:do_call calls ; hash
let trace t proc_name loc res in_footprint =
let tr_old =
try PnameLocHash.find t (proc_name, loc) with Not_found ->
PnameLocHash.add t (proc_name, loc) empty_trace ;
empty_trace
in
let tr_new = trace_add tr_old res in_footprint in
PnameLocHash.replace t (proc_name, loc) tr_new
let tr_elem_str (cr, in_footprint) =
let s1 =
match cr with
| CR_success ->
"OK"
| CR_not_met ->
"NotMet"
| CR_not_found ->
"NotFound"
| CR_skip ->
"Skip"
in
let s2 = if in_footprint then "FP" else "RE" in
s1 ^ ":" ^ s2
let pp_trace fmt tr = Pp.seq (fun fmt x -> F.fprintf fmt "%s" (tr_elem_str x)) fmt (List.rev tr)
let iter f t =
let elems = ref [] in
PnameLocHash.iter (fun x tr -> elems := (x, tr) :: !elems) t ;
let sorted_elems =
let compare (pname_loc1, _) (pname_loc2, _) =
[%compare : Typ.Procname.t * Location.t] pname_loc1 pname_loc2
in
List.sort ~cmp:compare !elems
in
List.iter ~f:(fun (x, tr) -> f x tr) sorted_elems
(*
let pp fmt t =
let do_call (pname, loc) tr =
F.fprintf fmt "%a %a: %a@\n" Typ.Procname.pp pname Location.pp loc pp_trace tr in
iter do_call t
*)
end
(** Execution statistics *)
type stats =
{ stats_failure: SymOp.failure_kind option
(** what type of failure stopped the analysis (if any) *)
; symops: int (** Number of SymOp's throughout the whole analysis of the function *)
; mutable nodes_visited_fp: IntSet.t (** Nodes visited during the footprint phase *)
; mutable nodes_visited_re: IntSet.t (** Nodes visited during the re-execution phase *)
; call_stats: CallStats.t }
; mutable nodes_visited_re: IntSet.t (** Nodes visited during the re-execution phase *) }
type status = Pending | Analyzed [@@deriving compare]
@ -537,11 +458,7 @@ let pp_summary_html source color fmt summary =
let empty_stats =
{ stats_failure= None
; symops= 0
; nodes_visited_fp= IntSet.empty
; nodes_visited_re= IntSet.empty
; call_stats= CallStats.init [] (* TODO(T23648322): remove the call_stats *) }
{stats_failure= None; symops= 0; nodes_visited_fp= IntSet.empty; nodes_visited_re= IntSet.empty}
let payload_compact sh payload =

27
infer/src/backend/specs.mli
Unescape View File

@ -72,38 +72,13 @@ module NormSpec : sig
(** Erase join info from pre of spec *)
end
(** module for tracing stats of function calls *)
module CallStats : sig
type t
(** kind of result of a procedure call *)
type call_result =
| CR_success (** successful call *)
| CR_not_met (** precondition not met *)
| CR_not_found (** the callee has no specs *)
| CR_skip (** the callee was skipped *)
(** trace of an occurrence of function call *)
type trace = (call_result * bool) list
val iter : (Typ.Procname.t * Location.t -> trace -> unit) -> t -> unit
(** iterate over results of procedure calls *)
val trace : t -> Typ.Procname.t -> Location.t -> call_result -> bool -> unit
(** trace a procedure call *)
val pp_trace : Format.formatter -> trace -> unit
(** pretty print a call trace *)
end
(** Execution statistics *)
type stats =
{ stats_failure: SymOp.failure_kind option
(** what type of failure stopped the analysis (if any) *)
; symops: int (** Number of SymOp's throughout the whole analysis of the function *)
; mutable nodes_visited_fp: IntSet.t (** Nodes visited during the footprint phase *)
; mutable nodes_visited_re: IntSet.t (** Nodes visited during the re-execution phase *)
; call_stats: CallStats.t }
; mutable nodes_visited_re: IntSet.t (** Nodes visited during the re-execution phase *) }
(** Analysis status of the procedure:
- Pending means that the summary has been created by the procedure has not been analyzed yet

4
infer/src/backend/symExec.ml
Unescape View File

@ -1078,8 +1078,8 @@ let rec sym_exec tenv current_pdesc instr_ (prop_: Prop.normal Prop.t) path
| None ->
()
| Some summary ->
Specs.CallStats.trace summary.Specs.stats.Specs.call_stats callee_pname loc
Specs.CallStats.CR_skip !Config.footprint ) ;
let proc_name = Specs.get_proc_name summary in
Tabulation.log_call_trace proc_name callee_pname loc Tabulation.CR_skip ) ;
unknown_or_scan_call ~is_scan:false ~reason ret_typ_opt ret_annots
Builtin.
{ pdesc= current_pdesc

63
infer/src/backend/tabulation.ml
Unescape View File

@ -25,6 +25,24 @@ type splitting =
; frame_typ: (Exp.t * Exp.t) list
; missing_typ: (Exp.t * Exp.t) list }
(** kind of result of a procedure call *)
type call_result =
| CR_success (** successful call *)
| CR_not_met (** precondition not met *)
| CR_not_found (** the callee has no specs *)
| CR_skip (** the callee was skipped *)
let string_of_call_result = function
| CR_success ->
"OK"
| CR_not_met ->
"NotMet"
| CR_not_found ->
"NotFound"
| CR_skip ->
"Skip"
type deref_error =
| Deref_freed of PredSymb.res_action (** dereference a freed pointer *)
| Deref_minusone (** dereference -1 *)
@ -65,6 +83,18 @@ let print_results tenv actual_pre results =
L.d_strln "***** END RESULTS FUNCTION CALL *******"
let log_call_trace caller_name callee_name loc res =
let call_trace =
EventLogger.CallTrace
{ call_location= loc
; call_result= string_of_call_result res
; callee_name= Typ.Procname.to_string callee_name
; caller_name= Typ.Procname.to_string caller_name
; lang= Typ.Procname.get_language caller_name |> Language.to_explicit_string }
in
if !Config.footprint then EventLogger.log call_trace else ()
(***************)
(** Rename the variables in the spec. *)
@ -102,7 +132,7 @@ let spec_find_rename trace_call summary : (int * Prop.exposed Specs.spec) list *
let specs = Specs.get_specs_from_payload summary in
let formals = Specs.get_formals summary in
if List.is_empty specs then (
trace_call Specs.CallStats.CR_not_found ;
trace_call CR_not_found ;
raise
(Exceptions.Precondition_not_found
(Localise.verbatim_desc (Typ.Procname.to_string proc_name), __POS__)) ) ;
@ -1223,17 +1253,17 @@ let exe_call_postprocess tenv ret_id trace_call callee_pname callee_attrs loc re
in
match error with
| Dereference_error (Deref_minusone, desc, path_opt) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
extend_path path_opt None ;
raise
(Exceptions.Dangling_pointer_dereference (Some PredSymb.DAminusone, desc, __POS__))
| Dereference_error (Deref_undef_exp, desc, path_opt) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
extend_path path_opt None ;
raise
(Exceptions.Dangling_pointer_dereference (Some PredSymb.DAuninit, desc, __POS__))
| Dereference_error (Deref_null pos, desc, path_opt) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
extend_path path_opt (Some pos) ;
if Localise.is_parameter_not_null_checked_desc desc then
raise (Exceptions.Parameter_not_null_checked (desc, __POS__))
@ -1245,15 +1275,15 @@ let exe_call_postprocess tenv ret_id trace_call callee_pname callee_attrs loc re
raise (Exceptions.Empty_vector_access (desc, __POS__))
else raise (Exceptions.Null_dereference (desc, __POS__))
| Dereference_error (Deref_freed _, desc, path_opt) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
extend_path path_opt None ;
raise (Exceptions.Use_after_free (desc, __POS__))
| Dereference_error (Deref_undef (_, _, pos), desc, path_opt) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
extend_path path_opt (Some pos) ;
raise (Exceptions.Skip_pointer_dereference (desc, __POS__))
| Prover_checks _ | Cannot_combine | Missing_sigma_not_empty | Missing_fld_not_empty ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
assert false )
| [] ->
(* no dereference error detected *)
@ -1263,7 +1293,7 @@ let exe_call_postprocess tenv ret_id trace_call callee_pname callee_attrs loc re
else if List.exists
~f:(function
| Prover_checks (check :: _) ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
let exn = get_check_exn tenv check callee_pname loc __POS__ in
raise exn
| _ ->
@ -1272,7 +1302,7 @@ let exe_call_postprocess tenv ret_id trace_call callee_pname callee_attrs loc re
then call_desc (Some Localise.Pnm_bounds)
else call_desc None
in
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
raise (Exceptions.Precondition_not_met (desc, __POS__))
else
(* combine the valid results, and store diverging states *)
@ -1304,14 +1334,14 @@ let exe_call_postprocess tenv ret_id trace_call callee_pname callee_attrs loc re
(List.map ~f:(fun vr -> (vr.vr_pi, vr.vr_cons_res)) valid_res_miss_pi)
with
| None ->
trace_call Specs.CallStats.CR_not_met ;
trace_call CR_not_met ;
raise (Exceptions.Precondition_not_met (call_desc None, __POS__))
| Some cover ->
L.d_strln "Found minimum cover" ;
List.iter ~f:print_pi (List.map ~f:fst cover) ;
List.concat_map ~f:snd cover )
in
trace_call Specs.CallStats.CR_success ;
trace_call CR_success ;
let res =
List.map
~f:(fun (p, path) -> (quantify_path_idents_remove_constant_strings tenv p, path))
@ -1347,16 +1377,13 @@ let exe_function_call callee_summary tenv ret_id_opt caller_pdesc callee_pname l
prop path =
let callee_attrs = Specs.get_attributes callee_summary in
let caller_pname = Procdesc.get_proc_name caller_pdesc in
let caller_summary = Specs.get_summary_unsafe "exe_function_call" caller_pname in
let trace_call res =
Specs.CallStats.trace caller_summary.Specs.stats.Specs.call_stats callee_pname loc res
!Config.footprint
in
let trace_call = log_call_trace caller_pname callee_pname loc in
let spec_list, formal_params = spec_find_rename trace_call callee_summary in
let nspecs = List.length spec_list in
L.d_strln
("Found " ^ string_of_int nspecs ^ " specs for function " ^ Typ.Procname.to_string callee_pname) ;
L.d_strln ("START EXECUTING SPECS FOR " ^ Typ.Procname.to_string callee_pname ^ " from state") ;
(F.sprintf "Found %d specs for function %s" nspecs (Typ.Procname.to_string callee_pname)) ;
L.d_strln
(F.sprintf "START EXECUTING SPECS FOR %s from state" (Typ.Procname.to_string callee_pname)) ;
Prop.d_prop prop ;
L.d_ln () ;
let exe_one_spec (n, spec) =

9
infer/src/backend/tabulation.mli
Unescape View File

@ -10,6 +10,15 @@
open! IStd
(** kind of result of a procedure call *)
type call_result =
| CR_success (** successful call *)
| CR_not_met (** precondition not met *)
| CR_not_found (** the callee has no specs *)
| CR_skip (** the callee was skipped *)
val log_call_trace : Typ.Procname.t -> Typ.Procname.t -> Location.t -> call_result -> unit
(** Interprocedural footprint analysis *)
val remove_constant_string_class : Tenv.t -> 'a Prop.t -> Prop.normal Prop.t

8
infer/src/base/Config.ml
Unescape View File

@ -857,12 +857,6 @@ and buck_out =
~meta:"dir" "Specify the root directory of buck-out"
and calls_csv =
CLOpt.mk_path_opt ~deprecated:["calls"] ~long:"calls-csv"
~in_help:InferCommand.([(Report, manual_generic)])
~meta:"file" "Write individual calls in CSV format to $(i,file)"
and capture =
CLOpt.mk_bool ~long:"capture" ~default:true
"capture and translate source files into infer's intermediate language for analysis"
@ -2265,8 +2259,6 @@ and buck_out = !buck_out
and bufferoverrun = !bufferoverrun
and calls_csv = !calls_csv
and capture =
(* take `--clang-frontend-action` as the source of truth as long as that option exists *)
match !clang_frontend_action with

2
infer/src/base/Config.mli
Unescape View File

@ -273,8 +273,6 @@ val buck_out : string option
val bufferoverrun : bool
val calls_csv : string option
val capture : bool
val captured_dir : string

26
infer/src/base/EventLogger.ml
Unescape View File

@ -105,6 +105,27 @@ let create_analysis_stats_row base record =
|> add_int ~key:"symops" ~data:record.symops
type call_trace =
{ call_location: Location.t
; call_result: string
; callee_name: string
; caller_name: string
; lang: string }
let create_call_trace_row base record =
let open JsonBuilder in
base
|> add_string ~key:"call_location"
~data:
(String.concat
[string_of_int record.call_location.line; ":"; string_of_int record.call_location.col])
|> add_string ~key:"source_file" ~data:(SourceFile.to_rel_path record.call_location.file)
|> add_string ~key:"call_result" ~data:record.call_result
|> add_string ~key:"callee_name" ~data:record.callee_name
|> add_string ~key:"caller_name" ~data:record.caller_name
|> add_string ~key:"lang" ~data:record.lang
type frontend_exception =
{ ast_node: string option
; exception_file: string
@ -155,6 +176,7 @@ let create_procedures_translated_row base record =
type event =
| AnalysisStats of analysis_stats
| CallTrace of call_trace
| FrontendException of frontend_exception
| ProceduresTranslatedSummary of procedures_translated
| UncaughtException of exn * int
@ -163,6 +185,8 @@ let string_of_event event =
match event with
| AnalysisStats _ ->
"AnalysisStats"
| CallTrace _ ->
"CallTrace"
| FrontendException _ ->
"FrontendException"
| ProceduresTranslatedSummary _ ->
@ -214,6 +238,8 @@ module LoggerImpl : S = struct
( match event with
| AnalysisStats record ->
create_analysis_stats_row base record
| CallTrace record ->
create_call_trace_row base record
| FrontendException record ->
create_frontend_exception_row base record
| ProceduresTranslatedSummary record ->

8
infer/src/base/EventLogger.mli
Unescape View File

@ -18,6 +18,13 @@ type analysis_stats =
; num_preposts: int
; symops: int }
type call_trace =
{ call_location: Location.t
; call_result: string
; callee_name: string
; caller_name: string
; lang: string }
type frontend_exception =
{ ast_node: string option
; exception_file: string
@ -35,6 +42,7 @@ type procedures_translated =
type event =
| AnalysisStats of analysis_stats
| CallTrace of call_trace
| FrontendException of frontend_exception
| ProceduresTranslatedSummary of procedures_translated
| UncaughtException of exn * int (** exception, exitcode *)

Write Preview
Loading…
Cancel
Save