Merge pull request #2 from rnburn/master

Use a more accurate method to determine endpoints on a request span.

opentracing/src/opentracing_request_instrumentor.cpp

@@ -1,6 +1,6 @@
 #include "opentracing_request_instrumentor.h"
-#include "utility.h"
 #include <iostream>
+#include "utility.h"
 
 extern "C" {
 extern ngx_module_t ngx_http_opentracing_module;
@@ -87,7 +87,9 @@ OpenTracingRequestInstrumentor::OpenTracingRequestInstrumentor(
                  "starting opentracing request span for %p", request_);
   request_span_ = tracer->StartSpan(
       get_request_operation_name(request_, core_loc_conf, loc_conf_),
-      {opentracing::ChildOf(parent_span_context.get())});
+      {opentracing::ChildOf(parent_span_context.get()),
+       opentracing::StartTimestamp{
+           to_system_timestamp(request->start_sec, request->start_msec)}});
   if (!request_span_) throw InstrumentationFailure{};
 
   if (loc_conf_->enable_locations) {
@@ -134,7 +136,8 @@ void OpenTracingRequestInstrumentor::on_change_block(
 //------------------------------------------------------------------------------
 // on_exit_block
 //------------------------------------------------------------------------------
-void OpenTracingRequestInstrumentor::on_exit_block() {
+void OpenTracingRequestInstrumentor::on_exit_block(
+    std::chrono::steady_clock::time_point finish_timestamp) {
   // Set default and custom tags for the block. Many nginx variables won't be
   // available when a block is first entered, so set tags when the block is
   // exited instead.
@@ -145,7 +148,7 @@ void OpenTracingRequestInstrumentor::on_exit_block() {
     add_script_tags(main_conf_->tags, request_, *span_);
     add_script_tags(loc_conf_->tags, request_, *span_);
     add_status_tags(request_, *span_);
-    span_->Finish();
+    span_->Finish({opentracing::FinishTimestamp{finish_timestamp}});
   } else {
     add_script_tags(loc_conf_->tags, request_, *request_span_);
   }
@@ -166,13 +169,21 @@ void OpenTracingRequestInstrumentor::set_request_span_context() {
 // on_log_request
 //------------------------------------------------------------------------------
 void OpenTracingRequestInstrumentor::on_log_request() {
-  on_exit_block();
+  // Follows the same logic to determine the time point that the request is
+  // finished as that for NGINX's $request_time variable. See
+  // http://nginx.org/en/docs/http/ngx_http_log_module.html#var_request_time
+  auto timepoint = ngx_timeofday();
+  auto finish_timestamp =
+      opentracing::convert_time_point<std::chrono::steady_clock>(
+          to_system_timestamp(timepoint->sec, timepoint->msec));
+
+  on_exit_block(finish_timestamp);
 
   ngx_log_debug1(NGX_LOG_DEBUG_HTTP, request_->connection->log, 0,
                  "finishing opentracing request span for %p", request_);
   add_status_tags(request_, *request_span_);
   add_script_tags(main_conf_->tags, request_, *request_span_);
 
-  request_span_->Finish();
+  request_span_->Finish({opentracing::FinishTimestamp{finish_timestamp}});
 }
 }  // namespace ngx_opentracing

opentracing/src/opentracing_request_instrumentor.h

@@ -1,6 +1,7 @@
 #pragma once
 
 #include <opentracing/tracer.h>
+#include <chrono>
 #include <exception>
 #include <memory>
 #include "opentracing_conf.h"
@@ -38,7 +39,9 @@ class OpenTracingRequestInstrumentor {
   std::unique_ptr<opentracing::Span> request_span_;
   std::unique_ptr<opentracing::Span> span_;
 
-  void on_exit_block();
+  void on_exit_block(std::chrono::steady_clock::time_point finish_timestamp =
+                         std::chrono::steady_clock::now());
+
   void set_request_span_context();
 };
 }  // namespace ngx_opentracing

opentracing/src/utility.cpp

@@ -28,4 +28,15 @@ ngx_str_t to_lower_ngx_str(ngx_pool_t *pool, const std::string &s) {
                  [](char c) { return std::tolower(c); });
   return result;
 }
+
+//------------------------------------------------------------------------------
+// to_system_timestamp
+//------------------------------------------------------------------------------
+std::chrono::system_clock::time_point to_system_timestamp(
+    time_t epoch_seconds, ngx_msec_t epoch_milliseconds) {
+  auto epoch_duration = std::chrono::seconds{epoch_seconds} +
+                        std::chrono::milliseconds{epoch_milliseconds};
+  return std::chrono::system_clock::from_time_t(std::time_t{0}) +
+         epoch_duration;
+}
 }  // namespace ngx_opentracing

opentracing/src/utility.h

@@ -4,6 +4,7 @@
 
 #include <algorithm>
 #include <cctype>
+#include <chrono>
 #include <string>
 
 extern "C" {
@@ -31,6 +32,14 @@ ngx_str_t to_ngx_str(ngx_pool_t *pool, const std::string &s);
 // Convert a std::string to an ngx_str_t and transforms it to lowercase.
 ngx_str_t to_lower_ngx_str(ngx_pool_t *pool, const std::string &s);
 
+//------------------------------------------------------------------------------
+// to_system_timestamp
+//------------------------------------------------------------------------------
+// Converts the epoch denoted by epoch_seconds, epoch_milliseconds to an
+// std::chrono::system_clock::time_point duration from the epoch.
+std::chrono::system_clock::time_point to_system_timestamp(
+    time_t epoch_seconds, ngx_msec_t epoch_milliseconds);
+
 //------------------------------------------------------------------------------
 // for_each
 //------------------------------------------------------------------------------