From a24c91930d20e9caaae4f1f1d68ba3cfe8b6bde2 Mon Sep 17 00:00:00 2001
From: Aaron Jacobs <aaron.jacobs@crescendotechnology.com>
Date: Mon, 6 Apr 2020 17:36:43 +0000
Subject: [PATCH] Add a timestamp to the Rook request object.

Requests objects now have a `httpuv.timestamp` member containing a
timestamp compatible with Sys.time().

This timestamp is captured when the request is received at the C++ level
in the background thread, which has two advantages:

1. We can much more accurately capture the total time the client
   actually waits for the request to get processed.

2. We can instrument the time it takes before the R-level callback
   actually runs.

More broadly, the timestamp makes it easier to log measures of request
latency in httpuv-based applications, and reduces the overhead of common
ways to do so -- e.g. using Plumber hooks.

Signed-off-by: Aaron Jacobs <aaron.jacobs@crescendotechnology.com>
---
 src/httprequest.cpp    | 10 ++++++++++
 src/httprequest.h      | 11 ++++++++++-
 src/webapplication.cpp |  4 ++++
 3 files changed, 24 insertions(+), 1 deletion(-)

diff --git a/src/httprequest.cpp b/src/httprequest.cpp
index 81ba0912..d7d3871f 100644
--- a/src/httprequest.cpp
+++ b/src/httprequest.cpp
@@ -176,6 +176,16 @@ std::string HttpRequest::url() const {
   return _url;
 }
 
+double HttpRequest::timestamp() const {
+  // According to the std::chrono docs, we need at least 55 bit here.
+  long long since_epoch = std::chrono::duration_cast<std::chrono::microseconds>(
+    _timestamp.time_since_epoch()
+  ).count();
+  // R's currentTime() returns a Unix timestamp with microseconds (or
+  // nanoseconds on supported platforms) tacked on.
+  return ((double) since_epoch) / 1e6;
+}
+
 const RequestHeaders& HttpRequest::headers() const {
   return _headers;
 }
diff --git a/src/httprequest.h b/src/httprequest.h
index f25370bf..752f97e6 100644
--- a/src/httprequest.h
+++ b/src/httprequest.h
@@ -3,6 +3,7 @@
 
 #include <map>
 #include <iostream>
+#include <chrono>
 
 #include <functional>
 #include <memory>
@@ -92,6 +93,10 @@ class HttpRequest : public WebSocketConnectionCallbacks,
   };
   LastHeaderState _last_header_state;
 
+  // Sys.time()-compatible timestamp, which can later be used to instrument
+  // roundtrip latency in R.
+  std::chrono::time_point<std::chrono::system_clock> _timestamp;
+
 public:
   HttpRequest(uv_loop_t* pLoop,
               std::shared_ptr<WebApplication> pWebApplication,
@@ -106,7 +111,8 @@ class HttpRequest : public WebSocketConnectionCallbacks,
       _is_upgrade(false),
       _response_scheduled(false),
       _handling_request(false),
-      _background_queue(backgroundQueue)
+      _background_queue(backgroundQueue),
+      _timestamp(std::chrono::system_clock::now())
   {
     ASSERT_BACKGROUND_THREAD()
     uv_tcp_init(pLoop, &_handle.tcp);
@@ -166,6 +172,9 @@ class HttpRequest : public WebSocketConnectionCallbacks,
   // pipelined HTTP requests.
   void requestCompleted();
 
+  // Returns timestamp compatible with R/Def.h's currentTime().
+  double timestamp() const;
+
   void _call_r_on_ws_open();
   void _schedule_on_headers_complete_complete(std::shared_ptr<HttpResponse> pResponse);
   void _on_headers_complete_complete(std::shared_ptr<HttpResponse> pResponse);
diff --git a/src/webapplication.cpp b/src/webapplication.cpp
index 068a9bbb..40c91cbc 100644
--- a/src/webapplication.cpp
+++ b/src/webapplication.cpp
@@ -150,6 +150,10 @@ void requestToEnv(std::shared_ptr<HttpRequest> pRequest, Rcpp::Environment* pEnv
   env["rook.version"] = CharacterVector("1.1-0");
   env["rook.url_scheme"] = CharacterVector("http");
 
+  NumericVector timestamp = NumericVector::create(pRequest->timestamp());
+  timestamp.attr("class") = CharacterVector({"POSIXct", "POSIXt"});
+  env["httpuv.timestamp"] = timestamp;
+
   Address addr = pRequest->serverAddress();
   env["SERVER_NAME"] = CharacterVector(addr.host);
   std::ostringstream portstr;