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

@@ -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;
 }

src/httprequest.h

@@ -3,6 +3,7 @@
 
 #include <map>
 #include <iostream>
+#include <chrono>
 
 #include <boost/function.hpp>
 #include <boost/bind.hpp>
@@ -82,6 +83,10 @@ class HttpRequest : public WebSocketConnectionCallbacks,
   // to schedule callbacks to run on the background thread.
   CallbackQueue* _background_queue;
 
+  // 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,
               boost::shared_ptr<WebApplication> pWebApplication,
@@ -96,7 +101,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);
@@ -154,6 +160,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(boost::shared_ptr<HttpResponse> pResponse);
   void _on_headers_complete_complete(boost::shared_ptr<HttpResponse> pResponse);

src/webapplication.cpp

@@ -150,6 +150,7 @@ void requestToEnv(boost::shared_ptr<HttpRequest> pRequest, Rcpp::Environment* pE
 
   env["rook.version"] = CharacterVector("1.1-0");
   env["rook.url_scheme"] = CharacterVector("http");
+  env["httpuv.timestamp"] = NumericVector::create(pRequest->timestamp());
 
   Address addr = pRequest->serverAddress();
   env["SERVER_NAME"] = CharacterVector(addr.host);