From e61f8f5a955bac645d5b1093512250ac7b1b1089 Mon Sep 17 00:00:00 2001
From: Lucian Wischik <ljw@fb.com>
Date: Wed, 8 Jul 2020 20:40:07 -0700
Subject: [PATCH] track monitor times for request-handling

Summary:
My overall goal is to track end-to-end all the timings involved in handling a request.

This diff contributes the timings that the monitor knows about. It stores them inside the `Connection_tracker.t` record which we're passing around from client to monitor to server back to client.

Reviewed By: CatherineGasnier

Differential Revision: D22417968

fbshipit-source-id: ba1b685a0df2fda49570487dcc9b9e1507f940d6
---
 hphp/hack/src/monitor/serverMonitor.ml     |  8 ++++++--
 hphp/hack/src/utils/connection_tracker.ml  | 10 ++++++++++
 hphp/hack/src/utils/connection_tracker.mli | 11 +++++++++++
 3 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/hphp/hack/src/monitor/serverMonitor.ml b/hphp/hack/src/monitor/serverMonitor.ml
index ec80879e45e..d2d056bc127 100644
--- a/hphp/hack/src/monitor/serverMonitor.ml
+++ b/hphp/hack/src/monitor/serverMonitor.ml
@@ -279,6 +279,7 @@ struct
     in
     match cmd with
     | MonitorRpc.HANDOFF_TO_SERVER (tracker, handoff_options) ->
+      tracker.Connection_tracker.t_received_handoff <- Unix.gettimeofday ();
       client_prehandoff
         ~tracker
         ~is_purgatory_client:false
@@ -299,6 +300,7 @@ struct
   and hand_off_client_connection ~tracker server_fd client_fd =
     let status = Libancillary.ancil_send_fd server_fd client_fd in
     if status = 0 then begin
+      tracker.Connection_tracker.t_sent_fd <- Unix.gettimeofday ();
       msg_to_channel server_fd tracker;
       Sent_fds_collector.cleanup_fd client_fd
     end else begin
@@ -377,14 +379,16 @@ struct
         @@ List.find_exn server.out_fds ~f:(fun x ->
                String.equal (fst x) handoff_options.MonitorRpc.pipe_name)
       in
-      let since_last_request = Unix.time () -. !(server.last_request_handoff) in
+      tracker.Connection_tracker.t_monitor_ready <- Unix.gettimeofday ();
       (* TODO: Send this to client so it is visible. *)
       log
         "Got %s request for typechecker. Prior request %.1f seconds ago"
         ~tracker
         handoff_options.MonitorRpc.pipe_name
-        since_last_request;
+        ( tracker.Connection_tracker.t_monitor_ready
+        -. !(server.last_request_handoff) );
       msg_to_channel client_fd (PH.Sentinel server.finale_file);
+      tracker.Connection_tracker.t_sent_ack_to_client <- Unix.gettimeofday ();
       hand_off_client_connection_with_retries ~tracker server_fd 8 client_fd;
       log "handed off client fd to server" ~tracker;
       HackEventLogger.client_connection_sent ();
diff --git a/hphp/hack/src/utils/connection_tracker.ml b/hphp/hack/src/utils/connection_tracker.ml
index 706c16ac71c..0249efcac43 100644
--- a/hphp/hack/src/utils/connection_tracker.ml
+++ b/hphp/hack/src/utils/connection_tracker.ml
@@ -20,6 +20,11 @@ type t = {
   mutable t_ready_to_send_cmd: float;
   mutable t_sent_cmd: float;
   mutable t_received_response: float;
+  (* monitor *)
+  mutable t_received_handoff: float;
+  mutable t_monitor_ready: float;
+  mutable t_sent_ack_to_client: float;
+  mutable t_sent_fd: float;
   (* server *)
   mutable t_sleep_and_check: float;
   mutable t_monitor_fd_ready: float;
@@ -54,6 +59,11 @@ let create () : t =
     t_ready_to_send_cmd = 0.;
     t_sent_cmd = 0.;
     t_received_response = 0.;
+    (* monitor *)
+    t_received_handoff = 0.;
+    t_monitor_ready = 0.;
+    t_sent_ack_to_client = 0.;
+    t_sent_fd = 0.;
     (* server *)
     t_sleep_and_check = 0.;
     t_monitor_fd_ready = 0.;
diff --git a/hphp/hack/src/utils/connection_tracker.mli b/hphp/hack/src/utils/connection_tracker.mli
index 1eafdc58c11..9f4f156d99c 100644
--- a/hphp/hack/src/utils/connection_tracker.mli
+++ b/hphp/hack/src/utils/connection_tracker.mli
@@ -34,6 +34,17 @@ type t = {
   mutable t_received_response: float;
       (** 11. client has received rpc response from server *)
   (*
+  MONITOR SIDE
+  *)
+  mutable t_received_handoff: float;
+      (** 1. The monitor received handoff from client *)
+  mutable t_monitor_ready: float;
+      (** 2. The monitor is now ready to do its work *)
+  mutable t_sent_ack_to_client: float;
+      (** 3. The monitor has sent an ack back to the client *)
+  mutable t_sent_fd: float;
+      (** 4. The monitor has sent fd to server. It will now send tracker. *)
+  (*
   SERVER SIDE
   *)
   mutable t_sleep_and_check: float;
-- 
2.11.4.GIT