Merge remote-tracking branch 'couchbase/morpheus' to master

* couchbase/morpheus:
  MB-70411: Include worker thread id in create failure message
  MB-70329: Add histogram for dispatch socket and notifications

Change-Id: I412dacc0d85aa17c2a62d54b5744a02ffdc2cc8a

Author: trondn

daemon/connection.cc

@@ -916,13 +916,15 @@ void Connection::processNotifiedCookie(
         Cookie& cookie,
         cb::engine_errc status,
         std::chrono::steady_clock::time_point scheduled) {
+    using namespace std::chrono;
+    const auto now = steady_clock::now();
+    cookie_notification_histogram[thread.index].add(
+            duration_cast<microseconds>(now - scheduled));
     Expects(cookie.isEwouldblock());
     cookie.setAiostat(status);
     cookie.clearEwouldblock();
     triggerCallback();
-    cookie.getTracer().record(cb::tracing::Code::Notified,
-                              scheduled,
-                              std::chrono::steady_clock::now());
+    cookie.getTracer().record(cb::tracing::Code::Notified, scheduled, now);
 }
 
 void Connection::commandExecuted(Cookie& cookie) {

daemon/front_end_thread.cc

@@ -72,6 +72,8 @@ nlohmann::json ClientConnectionDetails::to_json(
  */
 static std::vector<FrontEndThread> threads;
 std::vector<Hdr1sfMicroSecHistogram> scheduler_info;
+std::vector<Hdr1sfMicroSecHistogram> dispatch_socket_histogram;
+std::vector<Hdr1sfMicroSecHistogram> cookie_notification_histogram;
 
 /*
  * Number of worker threads that have finished setting themselves up.
@@ -309,11 +311,14 @@ void FrontEndThread::do_dispatch(SOCKET sfd,
         BucketManager::instance().associateInitialBucket(*c);
         success = true;
     } catch (const std::bad_alloc&) {
-        LOG_WARNING_RAW("Failed to allocate memory for connection");
+        LOG_WARNING_CTX("Failed to allocate memory for connection",
+                        {"worker_tid", index});
     } catch (const std::exception& error) {
-        LOG_WARNING_CTX("Failed to create connection", {"error", error.what()});
+        LOG_WARNING_CTX("Failed to create connection",
+                        {"error", error.what()},
+                        {"worker_tid", index});
     } catch (...) {
-        LOG_WARNING_RAW("Failed to create connection");
+        LOG_WARNING_CTX("Failed to create connection", {"worker_tid", index});
     }
 
     if (!success) {
@@ -382,8 +387,13 @@ void FrontEndThread::dispatch(SOCKET sfd,
     last_thread = tid;
 
     try {
-        thread.eventBase.runInEventBaseThread(
-                [&thread, sock = sfd, port = std::move(descr)]() {
+        using namespace std::chrono;
+        const auto scheduled = steady_clock::now();
+        thread.eventBase.runInEventBaseThreadAlwaysEnqueue(
+                [&thread, sock = sfd, port = std::move(descr), scheduled]() {
+                    const auto now = steady_clock::now();
+                    dispatch_socket_histogram[thread.index].add(
+                            duration_cast<microseconds>(now - scheduled));
                     thread.do_dispatch(sock, port);
                 });
     } catch (const std::bad_alloc& e) {
@@ -427,6 +437,8 @@ void worker_threads_init() {
     const auto nthr = Settings::instance().getNumWorkerThreads();
 
     scheduler_info.resize(nthr);
+    dispatch_socket_histogram.resize(nthr);
+    cookie_notification_histogram.resize(nthr);
 
     try {
         threads = std::vector<FrontEndThread>(nthr);

daemon/front_end_thread.h

@@ -275,3 +275,10 @@ struct FrontEndThread {
 class Hdr1sfMicroSecHistogram;
 
 extern std::vector<Hdr1sfMicroSecHistogram> scheduler_info;
+
+/// Histogram counting the time from a socket was accepted until
+/// it was dispatched on the correct front end thread
+extern std::vector<Hdr1sfMicroSecHistogram> dispatch_socket_histogram;
+
+/// Histogram counting the time spent for cookie notifications
+extern std::vector<Hdr1sfMicroSecHistogram> cookie_notification_histogram;

daemon/protocol/mcbp/stats_context.cc

@@ -137,21 +137,33 @@ static cb::engine_errc stat_sched_executor(const std::string& arg,
     if (arg.empty()) {
         for (size_t ii = 0; ii < Settings::instance().getNumWorkerThreads();
              ++ii) {
-            append_stats(fmt::format("Thread-{}", ii),
+            append_stats(fmt::format("Thread-{}-scheduler", ii),
                          scheduler_info[ii].to_string(),
                          cookie);
+            append_stats(fmt::format("Thread-{}-dispatch-socket", ii),
+                         dispatch_socket_histogram[ii].to_string(),
+                         cookie);
+            append_stats(fmt::format("Thread-{}-cookie-notification", ii),
+                         cookie_notification_histogram[ii].to_string(),
+                         cookie);
         }
         return cb::engine_errc::success;
     }
 
     if (arg == "aggregate") {
-        static const std::string key = {"Thread-aggregate"};
-        Hdr1sfMicroSecHistogram histogram{};
-        for (const auto& h : scheduler_info) {
-            histogram += h;
-        }
-        // Add the stat
-        append_stats(key, histogram.to_string(), cookie);
+        auto add = [&cookie](std::string_view key,
+                             const std::vector<Hdr1sfMicroSecHistogram>& data) {
+            Hdr1sfMicroSecHistogram histogram{};
+            for (const auto& h : data) {
+                histogram += h;
+            }
+            // Add the stat
+            append_stats(key, histogram.to_string(), cookie);
+        };
+        add("Thread-aggregate-scheduler", scheduler_info);
+        add("Thread-aggregate-dispatch-socket", dispatch_socket_histogram);
+        add("Thread-aggregate-cookie-notification",
+            cookie_notification_histogram);
         return cb::engine_errc::success;
     }
 

daemon/stats.cc

@@ -13,6 +13,7 @@
 #include "bucket_manager.h"
 #include "buckets.h"
 #include "external_auth_manager_thread.h"
+#include "front_end_thread.h"
 #include "mc_time.h"
 #include "mcaudit.h"
 #include "memcached.h"
@@ -245,6 +246,20 @@ cb::engine_errc server_prometheus_stats(
                 server_prometheus_metering(collector);
             }
         } else {
+            auto add =
+                    [&collector](
+                            auto key,
+                            const std::vector<Hdr1sfMicroSecHistogram>& data) {
+                        Hdr1sfMicroSecHistogram histogram{};
+                        for (const auto& h : data) {
+                            histogram += h;
+                        }
+                        collector.addStat(key, histogram);
+                    };
+            add(cb::stats::Key::dispatch_socket_histogram,
+                dispatch_socket_histogram);
+            add(cb::stats::Key::cookie_notification_histogram,
+                cookie_notification_histogram);
             try {
                 auto instance = sigar::SigarIface::New();
                 instance->iterate_threads([&kvCollector](auto tid,

statistics/stat_definitions.json

@@ -3017,6 +3017,20 @@
         "description": "Number of seconds the given thread has spent running according to the OS",
         "added": "7.6.0"
     },
+    {
+        "key": "dispatch_socket_histogram",
+        "description": "Histogram containing the time taken to dispatch a newly created socket to its worker thread",
+        "unit": "microseconds",
+        "type": "histogram",
+        "added": "7.6.10"
+    },
+    {
+        "key": "cookie_notification_histogram",
+        "description": "Histogram containing the time taken to schedule a notification for a cookie until it is run",
+        "unit": "microseconds",
+        "type": "histogram",
+        "added": "7.6.10"
+    },
     {
         "key": "conn_yields",
         "description": "The total number all clients in this bucket yield due to consuming the number of ops allowed for the current timeslice",

tests/testapp/testapp_stats.cc

@@ -644,7 +644,7 @@ TEST_P(StatsTest, TestSchedulerInfo) {
                 ++found;
             },
             "worker_thread_info");
-    EXPECT_GT(4, found);
+    EXPECT_GT(7, found);
 }
 
 TEST_P(StatsTest, TestSchedulerInfo_Aggregate) {
@@ -655,7 +655,7 @@ TEST_P(StatsTest, TestSchedulerInfo_Aggregate) {
                 ++found;
             },
             "worker_thread_info aggregate");
-    EXPECT_EQ(1, found);
+    EXPECT_EQ(3, found);
 }
 
 TEST_P(StatsTest, TestSchedulerInfo_InvalidSubcommand) {