MB-43680: Record JSON validation runtimes

Time the duration of JSON validation done as part of executing client
requests, recoring the timings to:

* A new trace span.
* A new per-bucket histogram.

The trace span will be reported as part of Slow operation logging -
for example:

    WARNING 57: Slow operation. {...,"trace":"... json_validate=6446937532739980:18555 ...

The histograms will be reported via mctimings using the stat key
'json_validate', this will be added to cbcollect_info via a future
ns_server patch.

Change-Id: I1c90ee8c815b7026dd42a9ec5b567f0519c3cec0
Reviewed-on: http://review.couchbase.org/c/kv_engine/+/143528
Tested-by: Build Bot <[email protected]>
Reviewed-by: Trond Norbye <[email protected]>

Author: daverigby

daemon/buckets.h

@@ -134,6 +134,9 @@ class Bucket {
      */
     Hdr1sfMicroSecHistogram subjson_operation_times;
 
+    /// JSON_checker validate() execution time histogram.
+    Hdr1sfMicroSecHistogram jsonValidateTimes;
+
     /// Snappy decompression time histogram.
     Hdr1sfMicroSecHistogram snappyDecompressionTimes;
 

daemon/protocol/mcbp/stats_context.cc

@@ -333,6 +333,18 @@ static ENGINE_ERROR_CODE stat_histogram_executor(
     }
 }
 
+/**
+ * Handler for the <code>stats json_validate</code> command used to retrieve
+ * histograms of how long it took to validate JSON.
+ *
+ * @param arg - should be empty
+ * @param cookie the command context
+ */
+static ENGINE_ERROR_CODE stat_json_validate_executor(const std::string& arg,
+                                                     Cookie& cookie) {
+    return stat_histogram_executor(arg, cookie, &Bucket::jsonValidateTimes);
+}
+
 /**
  * Handler for the <code>stats topkeys</code> command used to retrieve
  * the most popular keys in the attached bucket.
@@ -583,6 +595,8 @@ static std::unordered_map<std::string, struct command_stat_handler>
                 {"aggregate", {false, true, true, stat_aggregate_executor}},
                 {"connections",
                  {false, false, true, stat_connections_executor}},
+                {"json_validate",
+                 {false, true, true, stat_json_validate_executor}},
                 {"topkeys", {false, true, true, stat_topkeys_executor}},
                 {"topkeys_json",
                  {false, true, true, stat_topkeys_json_executor}},

daemon/protocol/mcbp/steppable_command_context.cc

@@ -17,12 +17,16 @@
 #include "steppable_command_context.h"
 #include "executors.h"
 
+#include <daemon/buckets.h>
 #include <daemon/connection.h>
 #include <daemon/cookie.h>
 #include <daemon/front_end_thread.h>
 #include <daemon/memcached.h>
 #include <daemon/stats.h>
 #include <logger/logger.h>
+#include <platform/histogram.h>
+#include <platform/scope_timer.h>
+#include <utilities/hdrhistogram.h>
 
 SteppableCommandContext::SteppableCommandContext(Cookie& cookie_)
     : cookie(cookie_), connection(cookie.getConnection()) {
@@ -60,6 +64,14 @@ void SteppableCommandContext::drive() {
 void SteppableCommandContext::setDatatypeJSONFromValue(
         const cb::const_byte_buffer& value,
         protocol_binary_datatype_t& datatype) {
+    // Record how long JSON checking takes to both Tracer and bucket-level
+    // histogram.
+    using namespace cb::tracing;
+    ScopeTimer2<HdrMicroSecStopwatch, SpanStopwatch> timer(
+            std::forward_as_tuple(
+                    cookie.getConnection().getBucket().jsonValidateTimes),
+            std::forward_as_tuple(cookie, Code::JsonValidate));
+
     // Determine if document is JSON or not. We do not trust what the client
     // sent - instead we check for ourselves.
     if (connection.getThread().validator.validate(value.data(), value.size())) {

include/memcached/tracer.h

@@ -29,6 +29,8 @@ enum class Code : uint8_t {
     Request,
     /// Time spent decompressing Snappy data.
     SnappyDecompress,
+    /// Time spent validating if incoming value is JSON.
+    JsonValidate,
     /// Time spent waiting for a background fetch operation to be scheduled.
     BackgroundWait,
     /// Time spent performing the actual background load from disk.

tracing/tracer.cc

@@ -132,6 +132,8 @@ MEMCACHED_PUBLIC_API std::string to_string(const cb::tracing::Code tracecode) {
         return "request";
     case Code::SnappyDecompress:
         return "snappy.decompress";
+    case Code::JsonValidate:
+        return "json_validate";
     case Code::BackgroundWait:
         return "bg.wait";
     case Code::BackgroundLoad: