[infer][realtime log] initial scuba API

Summary:
API and stub implementation for real-time logging capabilities.
Low-level implementation requires interaction with FB-specific deployment of Scribe, hence it is stubbed out.

Reviewed By: jberdine

Differential Revision: D15259559

fbshipit-source-id: 712cb99e1

infer/man/man1/infer-full.txt

@@ -1568,6 +1568,10 @@ INTERNAL OPTIONS
            Reset the list of folders containing linters definitions to be
            empty (see linters-def-folder).
 
+       --scuba-logging
+           Activates: (direct) logging to scuba (Conversely:
+           --no-scuba-logging)
+
        --seconds-per-iteration float
            Set the number of seconds per iteration (see --iterations)
 

infer/src/backend/InferAnalyze.ml

@@ -85,6 +85,7 @@ let main ~changed_files =
     if result then incr n_source_files_to_analyze ;
     result
   in
+  ScubaEventLogging.log_count ~name:"source_files_to_analyze" ~value:!n_source_files_to_analyze ;
   let source_files_to_analyze = SourceFiles.get_all ~filter () in
   L.progress "Found %d%s source file%s to analyze in %s@." !n_source_files_to_analyze
     ( if Config.reactive_mode || Option.is_some changed_files then

infer/src/base/Config.ml

@@ -2012,6 +2012,8 @@ and select =
     "Select bug number $(i,N). If omitted, prompt for input."
 
 
+and scuba_logging = CLOpt.mk_bool ~long:"scuba-logging" "(direct) logging to scuba "
+
 and siof_safe_methods =
   CLOpt.mk_string_list ~long:"siof-safe-methods"
     ~in_help:InferCommand.[(Analyze, manual_siof)]
@@ -2988,6 +2990,8 @@ and seconds_per_iteration = !seconds_per_iteration
 
 and select = !select
 
+and scuba_logging = !scuba_logging
+
 and show_buckets = !print_buckets
 
 and siof = !siof

infer/src/base/Config.mli

@@ -598,6 +598,8 @@ val rest : string list
 
 val results_dir : string
 
+val scuba_logging : bool
+
 val seconds_per_iteration : float option
 
 val select : int option

infer/src/deadcode/Makefile

@@ -46,7 +46,7 @@ depend:
 	ocamldep -native \
 	  -I IR -I absint -I atd -I backend -I base -I biabduction -I bufferoverrun -I checkers \
 	  -I clang -I concurrency -I facebook -I integration -I istd -I java \
-	  -I labs -I nullsafe -I pulse -I quandary -I topl -I unit -I unit/clang -I deadcode \
+	  -I labs -I nullsafe -I pulse -I scuba -I quandary -I topl -I unit -I unit/clang -I deadcode \
 	   $(ml_src_files) > deadcode/.depend
 
 # circular dependency... not sure how to fix properly

infer/src/dune.in

@@ -24,6 +24,7 @@ let source_dirs =
        ; "nullsafe"
        ; "pulse"
        ; "quandary"
+       ; "scuba"
        ; "topl"
        ; "unit" ] )
 

infer/src/infer.ml

@@ -22,6 +22,8 @@ let run driver_mode =
   run_epilogue ()
 
 
+let run driver_mode = ScubaEventLogging.execute_with_time_logging "run" (fun () -> run driver_mode)
+
 let setup () =
   ( match Config.command with
   | Analyze ->

infer/src/integration/Driver.ml

@@ -305,6 +305,10 @@ let capture ~changed_files mode =
   PerfEvent.(log (fun logger -> log_end_event logger ()))
 
 
+let capture ~changed_files mode =
+  ScubaEventLogging.execute_with_time_logging "capture" (fun () -> capture ~changed_files mode)
+
+
 let execute_analyze ~changed_files =
   register_perf_stats_report PerfStats.TotalBackend ;
   InferAnalyze.main ~changed_files ;
@@ -407,6 +411,11 @@ let analyze_and_report ?suppress_console_report ~changed_files mode =
   if should_report && Config.report then report ?suppress_console:suppress_console_report ()
 
 
+let analyze_and_report ?suppress_console_report ~changed_files mode =
+  ScubaEventLogging.execute_with_time_logging "analyze_and_report" (fun () ->
+      analyze_and_report ?suppress_console_report ~changed_files mode )
+
+
 (** as the Config.fail_on_bug flag mandates, exit with error when an issue is reported *)
 let fail_on_issue_epilogue () =
   let issues_json =
@@ -549,6 +558,10 @@ let run_prologue mode =
   ()
 
 
+let run_prologue mode =
+  ScubaEventLogging.execute_with_time_logging "run_prologue" (fun () -> run_prologue mode)
+
+
 let run_epilogue () =
   if CLOpt.is_originator then (
     if Config.developer_mode then StatsAggregator.generate_files () ;
@@ -558,6 +571,8 @@ let run_epilogue () =
   ()
 
 
+let run_epilogue () = ScubaEventLogging.execute_with_time_logging "run_epilogue" run_epilogue
+
 let read_config_changed_files () =
   match Config.changed_files_index with
   | None ->

infer/src/opensource/Scribe.ml

@@ -0,0 +1,12 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+
+type category = InferEvents
+
+let log _ _ = ()

infer/src/opensource/Scribe.mli

@@ -0,0 +1,12 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+
+type category = InferEvents
+
+val log : category -> string list -> unit

infer/src/scuba/Scuba.ml

@@ -0,0 +1,59 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+(* FB-ONLY *)
+
+open! IStd
+module SMap = Map.Make (String)
+
+type table = InferEvents
+
+type sample =
+  { int_section: int SMap.t  (** All integer type fields and their values *)
+  ; normal_section: string SMap.t
+        (** All string (normal in Scuba terminology) type fields and their values *) }
+
+let new_sample ~time =
+  let time = match time with Some time -> time | None -> int_of_float (Unix.time ()) in
+  { (* time is a single mandatory field in scuba. without it,
+      scuba disregards all samples *)
+    int_section= SMap.singleton "time" time
+  ; normal_section= SMap.empty }
+
+
+let add_int ~name ~value sample =
+  let int_section = SMap.set sample.int_section ~key:name ~data:value in
+  {sample with int_section}
+
+
+let add_normal ~name ~value sample =
+  let normal_section = SMap.set sample.normal_section ~key:name ~data:value in
+  {sample with normal_section}
+
+
+let sample_to_json sample =
+  let map_to_assoc value_to_json key_value_map =
+    let pairs = SMap.to_alist key_value_map in
+    let assocs = List.map pairs ~f:(fun (name, data) -> (name, value_to_json data)) in
+    `Assoc assocs
+  in
+  let ints_to_assoc = map_to_assoc (fun data -> `Int data) in
+  let normals_to_assoc = map_to_assoc (fun data -> `String data) in
+  `Assoc
+    [("int", ints_to_assoc sample.int_section); ("normal", normals_to_assoc sample.normal_section)]
+
+
+let sample_to_json_string sample = sample |> sample_to_json |> Yojson.Basic.to_string
+
+let table_to_scribe_category = function InferEvents -> Scribe.InferEvents
+
+let log table samples =
+  let category = table_to_scribe_category table in
+  Scribe.log category (List.map samples ~f:sample_to_json_string)
+
+
+let log = if Config.scuba_logging then log else fun _ _ -> ()

infer/src/scuba/Scuba.mli

@@ -0,0 +1,45 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+
+(* FB-ONLY *)
+
+(**
+   Low-level Scuba logging functionality.
+   Provides functionality to log anything to any scuba table.
+   (Note that Scuba is a schema-free storage, so it won't require any changes).
+   Don't use this module directly for logging to tables with known structure.
+   Use high-level functions that are aware of the table structure.
+ *)
+
+(** A scuba table *)
+type table = InferEvents
+
+(** A sample to be added to Scuba *)
+type sample
+
+val new_sample : time:int option -> sample
+(** Create an empty sample with given creation timestamp. If time is not specified,
+    corresponds to current timestamp. *)
+
+val add_int : name:string -> value:int -> sample -> sample
+(**
+   Set a new integer field and its value to the sample.
+   Overwrites if a field with this name was already set.
+ *)
+
+val add_normal : name:string -> value:string -> sample -> sample
+(**
+   Set a new string (normal in Scuba terminology) field and its value to the sample.
+   Overwrites if a field with this name was already set.
+ *)
+
+val log : table -> sample list -> unit
+(**
+   The main function. Log a collection of samples to the given table.
+ *)

infer/src/scuba/ScubaEventLogging.ml

@@ -0,0 +1,59 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+(* FB-ONLY *)
+
+(*
+ * Utilities to log in "infer_events" key-value scuba table.
+ *)
+open! IStd
+
+let hostname = Unix.gethostname ()
+
+let maybe_add_normal ~name ~value sample =
+  match value with None -> sample | Some value -> Scuba.add_normal ~name ~value sample
+
+
+let set_common_fields sample =
+  let open Scuba in
+  sample
+  |> add_int ~name:"pid" ~value:(ProcessPoolState.get_pid () |> Pid.to_int)
+  |> add_int ~name:"is_main_process" ~value:(Bool.to_int CommandLineOption.is_originator)
+  |> add_normal ~name:"hostname" ~value:hostname
+  |> maybe_add_normal ~name:"job_id" ~value:Config.job_id
+  |> add_normal ~name:"command" ~value:(InferCommand.to_string Config.command)
+  |> add_normal ~name:"infer_commit" ~value:Version.commit
+
+
+let create_sample ~event_name ~value =
+  Scuba.new_sample ~time:None |> set_common_fields
+  |> Scuba.add_normal ~name:"event" ~value:event_name
+  |> Scuba.add_int ~name:"value" ~value
+
+
+type event_type = Count | Time
+
+let string_of_event_type = function Count -> "count" | Time -> "time"
+
+let log event_type ~event_suffix ~value =
+  let event_name = string_of_event_type event_type ^ "." ^ event_suffix in
+  let sample = create_sample ~event_name ~value in
+  Scuba.log Scuba.InferEvents [sample]
+
+
+(* If scuba logging is disabled, we would not log anyway, but let's not even try
+   to create samples to save perf *)
+let log = if Config.scuba_logging then log else fun _ ~event_suffix:_ ~value:_ -> ()
+
+let log_count ~name ~value = log Count ~event_suffix:name ~value
+
+let log_time ~name ~duration_ms = log Time ~event_suffix:name ~value:duration_ms
+
+let execute_with_time_logging name f =
+  let start_time = Mtime_clock.counter () in
+  let ret_val = f () in
+  let duration_ms = Mtime_clock.count start_time |> Mtime.Span.to_ms |> int_of_float in
+  log_time ~name ~duration_ms ; ret_val

infer/src/scuba/ScubaEventLogging.mli

@@ -0,0 +1,32 @@
+(*
+ * Copyright (c) 2019-present, Facebook, Inc.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *)
+
+open! IStd
+
+(* FB-ONLY *)
+
+(**
+   Functionality for logging into "infer_events" Scuba table.
+   The table is organized in form of key-value pairs.
+   Two most important fields are "event" and "value".
+   Other fields in the table correspond to things common for this particular
+   run of Infer.
+ *)
+
+val log_count : name:string -> value:int -> unit
+(** Log anything that can be counted. Events will be prefixed with "count." *)
+
+val execute_with_time_logging : string -> (unit -> 'a) -> 'a
+(**
+    A helper to log execution time of a particular function.
+    Use this to measure a performance of a given function.
+    Example:
+    {|
+      let f a b = <some code>
+      let f a b = ScubaEventLogging.execute_with_time_logging "f" (fun () -> f a b)
+    |}
+ *)