Include CPU times in profiling

Summary:
Our automated performance profiling thus far has been using wall
times. Wall times are somewhat sensitive to environmental factors, though. The
hope is that CPU times will be more reliable.

This is a little tricky, since each worker needs to record its own CPU times
and send them back to the master process. Luckily, we already have the
`Measure` library which does this :)

Reviewed By: samwgoldman

Differential Revision: D4282968

fbshipit-source-id: c8a989c0b97d501d48d032852d40a5c91da4d9bd

Author: gabelevi

hack/heap/sharedMem.ml

@@ -199,7 +199,7 @@ external hh_check_heap_overflow: unit -> bool  = "hh_check_heap_overflow"
 
 let init_done () =
   hh_init_done ();
-  Measure.print_stats ();
+  if hh_log_level() > 0 then Measure.print_stats ();
   EventLogger.sharedmem_init_done (heap_size ())
 
 type table_stats = {

hack/procs/worker.ml

@@ -139,7 +139,15 @@ and 'a slave = {
  *****************************************************************************)
 
 let slave_main ic oc =
+  let start_user_time = ref 0.0 in
+  let start_system_time = ref 0.0 in
   let send_result data =
+    let tm = Unix.times () in
+    let end_user_time = tm.Unix.tms_utime +. tm.Unix.tms_cutime in
+    let end_system_time = tm.Unix.tms_stime +. tm.Unix.tms_cstime in
+    Measure.sample "worker_user_time" (end_user_time -. !start_user_time);
+    Measure.sample "worker_system_time" (end_system_time -. !start_system_time);
+
     let stats = Measure.serialize (Measure.pop_global ()) in
     let s = Marshal.to_string (data,stats) [Marshal.Closures] in
     let len = String.length s in
@@ -154,7 +162,11 @@ let slave_main ic oc =
     Daemon.output_string oc s;
     Daemon.flush oc in
   try
+    Measure.push_global ();
     let Request do_process = Daemon.from_channel ic in
+    let tm = Unix.times () in
+    start_user_time := tm.Unix.tms_utime +. tm.Unix.tms_cutime;
+    start_system_time := tm.Unix.tms_stime +. tm.Unix.tms_cstime;
     do_process { send = send_result };
     exit 0
   with

hack/utils/measure.ml

@@ -239,6 +239,12 @@ let time (type a) ?record name (f: unit -> a) : a =
   sample ~record name (end_time -. start_time);
   ret
 
+let get_sum ?record name =
+  let record = get_record record in
+  match SMap.get name !record with
+  | None -> None
+  | Some { count; mean; _; } -> Some (float_of_int count *. mean)
+
 let pretty_num f =
   if f > 1000000000.0
   then Printf.sprintf "%.3fG" (f /. 1000000000.0)

hack/utils/measure.mli

@@ -26,6 +26,8 @@ val time: ?record:record -> string -> (unit -> 'a) -> 'a
 
 val merge: ?record:record -> from:record -> unit
 
+val get_sum: ?record:record -> string -> float option
+
 val print_entry_stats: ?record:record -> string -> unit
 val print_stats: ?record:record -> unit -> unit
 val print_entry_distribution: ?record:record -> string -> unit

src/common/profiling_js.ml

@@ -16,21 +16,63 @@
    val get_finished_timer: timer:string -> t -> (float * float) option
    val to_json: t -> Hh_json.json
  end = struct
+  type time_measurement = {
+    start_age: float;
+    duration: float;
+  }
+
   type result = {
-    start_wall_age: float;
-    wall_duration: float;
+    user: time_measurement;
+    system: time_measurement;
+    worker_user: time_measurement;
+    worker_system: time_measurement;
+    wall: time_measurement;
+  }
+
+  type running_timer = {
+    user_start: float;
+    system_start: float;
+    worker_user_start: float;
+    worker_system_start: float;
+    wall_start: float;
   }
 
   type t = {
-    running_timers: float SMap.t;
+    running_timers: running_timer SMap.t;
     results: result SMap.t;
   }
 
   let empty = { running_timers = SMap.empty; results = SMap.empty }
 
+  (* Returns the user cpu and system cpu times *)
+  let times () = Unix.(
+    let tm = times () in
+    (* Warning - cutime and cstime (children times) don't work on Windows *)
+    (tm.tms_utime +. tm.tms_cutime, tm.tms_stime +. tm.tms_cstime)
+  )
+
+  let worker_times () =
+    let worker_user_time = match Measure.get_sum "worker_user_time" with
+    | None -> 0.0
+    | Some time -> time in
+    let worker_system_time = match Measure.get_sum "worker_system_time" with
+    | None -> 0.0
+    | Some time -> time in
+    (worker_user_time, worker_system_time)
+
   let start_timer ~timer { running_timers; results; } =
+    let wall_start = Unix.gettimeofday () in
+    let (user_start, system_start) = times () in
+    let (worker_user_start, worker_system_start) = worker_times () in
+    let running_timer = {
+      user_start;
+      system_start;
+      worker_user_start;
+      worker_system_start;
+      wall_start;
+    } in
     {
-      running_timers = SMap.add timer (Unix.gettimeofday ()) running_timers;
+      running_timers = SMap.add timer running_timer running_timers;
       results;
     }
 
@@ -39,10 +81,31 @@
   let stop_timer ~timer { running_timers; results; } =
     match SMap.get timer running_timers with
     | None -> { running_timers; results; }
-    | Some timer_start_time ->
+    | Some running_timer ->
+        let wall_end = Unix.gettimeofday () in
+        let (user_end, system_end) = times () in
+        let (worker_user_end, worker_system_end) = worker_times () in
         let result = {
-          start_wall_age = timer_start_time -. flow_start_time;
-          wall_duration = Unix.gettimeofday () -. timer_start_time;
+          user = {
+            start_age= running_timer.user_start;
+            duration= user_end -. running_timer.user_start;
+          };
+          system = {
+            start_age= running_timer.system_start;
+            duration= system_end -. running_timer.system_start;
+          };
+          worker_user = {
+            start_age= running_timer.worker_user_start;
+            duration= worker_user_end -. running_timer.worker_user_start;
+          };
+          worker_system = {
+            start_age= running_timer.worker_system_start;
+            duration= worker_system_end -. running_timer.worker_system_start;
+          };
+          wall = {
+            start_age = running_timer.wall_start -. flow_start_time;
+            duration = wall_end -. running_timer.wall_start;
+          }
         } in
         {
           running_timers = SMap.remove timer running_timers;
@@ -52,15 +115,29 @@
   let get_finished_timer ~timer { results; _; } =
     match SMap.get timer results with
     | None -> None
-    | Some { start_wall_age; wall_duration; } ->
-        Some (start_wall_age, wall_duration)
+    | Some { wall = { start_age; duration; }; _; } ->
+        Some (start_age, duration)
+
+  let json_of_time_measurement { start_age; duration; } =
+    let open Hh_json in
+    let open Utils_js in
+    JSON_Object [
+      "start_age", JSON_Number (string_of_float_trunc start_age);
+      "duration", JSON_Number (string_of_float_trunc duration);
+    ]
 
-  let json_of_result { start_wall_age; wall_duration; } =
+  let json_of_result { wall; user; system; worker_user; worker_system; } =
     let open Hh_json in
     let open Utils_js in
     JSON_Object [
-      "start_wall_age", JSON_Number (string_of_float_trunc start_wall_age);
-      "wall_duration", JSON_Number (string_of_float_trunc wall_duration);
+      "wall", json_of_time_measurement wall;
+      "user", json_of_time_measurement user;
+      "system", json_of_time_measurement system;
+      "worker_user", json_of_time_measurement worker_user;
+      "worker_system", json_of_time_measurement worker_system;
+      (* legacy fields *)
+      "start_wall_age", JSON_Number (string_of_float_trunc wall.start_age);
+      "wall_duration", JSON_Number (string_of_float_trunc wall.duration);
     ]
 
   let to_json { results; _; } =