Add instrumentation logging around speculative execution

Author: mpenick

src/request_handler.cpp

@@ -167,6 +167,24 @@ RequestHandler::RequestHandler(const Request::ConstPtr& request, const ResponseF
     , manager_(NULL)
     , metrics_(metrics) {}
 
+RequestHandler::~RequestHandler() {
+  if (Logger::log_level() >= CASS_LOG_TRACE) {
+    OStringStream ss;
+    for (RequestTryVec::const_iterator it = request_tries_.begin(), end = request_tries_.end();
+         it != end; ++it) {
+      if (it != request_tries_.begin()) ss << ", ";
+      ss << "(" << it->address << ", ";
+      if (it->error != CASS_OK) {
+        ss << cass_error_desc(it->error);
+      } else {
+        ss << it->latency;
+      }
+      ss << ")";
+    }
+    LOG_TRACE("Speculative execution attempts: [%s]", ss.str().c_str());
+  }
+}
+
 void RequestHandler::set_prepared_metadata(const PreparedMetadata::Entry::Ptr& entry) {
   wrapper_.set_prepared_metadata(entry);
 }
@@ -269,6 +287,10 @@ void RequestHandler::set_response(const Host::Ptr& host, const Response::Ptr& re
       metrics_->record_speculative_request(uv_hrtime() - start_time_ns_);
     }
   }
+
+  if (Logger::log_level() >= CASS_LOG_TRACE) {
+    request_tries_.push_back(RequestTry(host->address(), uv_hrtime() - start_time_ns_));
+  }
 }
 
 void RequestHandler::set_error(CassError code, const String& message) {
@@ -289,6 +311,9 @@ void RequestHandler::set_error(const Host::Ptr& host, CassError code, const Stri
       set_error(code, message);
     }
   }
+  if (Logger::log_level() >= CASS_LOG_TRACE) {
+    request_tries_.push_back(RequestTry(host->address(), code));
+  }
 }
 
 void RequestHandler::set_error_with_error_response(const Host::Ptr& host,
@@ -297,6 +322,9 @@ void RequestHandler::set_error_with_error_response(const Host::Ptr& host,
   stop_request();
   running_executions_--;
   future_->set_error_with_response(host->address(), error, code, message);
+  if (Logger::log_level() >= CASS_LOG_TRACE) {
+    request_tries_.push_back(RequestTry(host->address(), code));
+  }
 }
 
 void RequestHandler::stop_timer() { timer_.stop(); }

src/request_handler.hpp

@@ -47,6 +47,28 @@ class ExecutionProfile;
 class Timer;
 class TokenMap;
 
+struct RequestTry {
+  RequestTry()
+      : error(CASS_OK)
+      , latency(0) {}
+
+  RequestTry(const Address& address, uint64_t latency)
+      : address(address)
+      , error(CASS_OK)
+      , latency(latency / (1000 * 1000)) {} // To milliseconds
+
+  RequestTry(const Address& address, CassError error)
+      : address(address)
+      , error(error)
+      , latency(0) {}
+
+  Address address;
+  CassError error;
+  uint64_t latency;
+};
+
+typedef SmallVector<RequestTry, 2> RequestTryVec;
+
 class ResponseFuture : public Future {
 public:
   typedef SharedRefPtr<ResponseFuture> Ptr;
@@ -138,6 +160,7 @@ class RequestHandler : public RefCounted<RequestHandler> {
 
   RequestHandler(const Request::ConstPtr& request, const ResponseFuture::Ptr& future,
                  Metrics* metrics = NULL);
+  ~RequestHandler();
 
   void set_prepared_metadata(const PreparedMetadata::Entry::Ptr& entry);
 
@@ -210,6 +233,8 @@ class RequestHandler : public RefCounted<RequestHandler> {
   ConnectionPoolManager* manager_;
 
   Metrics* const metrics_;
+
+  RequestTryVec request_tries_;
 };
 
 class KeyspaceChangedResponse {