SERVER-91920: Report admission and execution control queue stats in logs for slow transactions (#28867)

GitOrigin-RevId: 369a61cc993df6f77285b9b675ddc1f80de39154

Author: drew-beckmen

jstests/core/administrative/getlog2.js

@@ -62,7 +62,7 @@ assert(contains(query.log, function(v) {
     print(v);
     return stringContains(v, " find ") && stringContains(v, "filter:") &&
         stringContains(v, "keysExamined:") && stringContains(v, "docsExamined:") &&
-        v.indexOf("SENTINEL") != -1;
+        stringContains(v, "queues") && v.indexOf("SENTINEL") != -1;
 }));
 
 // 2. Run a slow update

jstests/noPassthrough/architecture/ticket_queue_slow_log.js

@@ -1,6 +1,7 @@
 /**
  * Test that verifies that time waiting for a ticket is logged as part of slow query logging.
- * Induces queueing for ticket by exhausting read tickets.
+ * Induces queueing for ticket by exhausting read tickets. Also verifies that ingress
+ * admission queueing stats are included in slow query logging.
  */
 
 import {ReplSetTest} from "jstests/libs/replsettest.js";
@@ -83,8 +84,10 @@ for (let i = 0; i < queuedReaders.length; i++) {
     queuedReaders[i]();
 }
 
-const predicate = new RegExp(
-    `Slow query.*"${coll}.*"queues".*"execution":{"admissions":\\d+,"totalTimeQueuedMicros":\\d+}`);
+const predicate =
+    new RegExp(`Slow query.*"${coll}.*"queues".*` +
+               `"(execution|ingress)":{"admissions":\\d+(?:,"totalTimeQueuedMicros":\\d+)?}` +
+               `.*"(execution|ingress)":{"admissions":\\d+(?:,"totalTimeQueuedMicros":\\d+)?}`);
 assert(checkLog.checkContainsOnce(primary, predicate),
        "Could not find log containing " + predicate);
 

src/mongo/db/BUILD.bazel

@@ -932,6 +932,7 @@ mongo_cc_library(
         "//src/mongo/util:fail_point",  # TODO(SERVER-93876): Remove.
         "//src/mongo/util:progress_meter",
         "//src/mongo/util/concurrency:spin_lock",  # TODO(SERVER-93876): Remove.
+        "//src/mongo/util/concurrency:ticketholder_queue_stats",
     ] + select({
         "//bazel/config:use_tracing_profiler_enabled": [
             "//src/mongo/util/tracing_profiler",  # TODO(SERVER-93876): Remove.

src/mongo/db/admission/BUILD.bazel

@@ -26,7 +26,6 @@ mongo_cc_library(
     deps = [
         ":ingress_admission_context",
         "//src/mongo:base",  # TODO(SERVER-93876): Remove.
-        "//src/mongo/db:commands",  # TODO(SERVER-93876): Remove.
         "//src/mongo/db:server_base",  # TODO(SERVER-93876): Remove.
         "//src/mongo/db:server_feature_flags",  # TODO(SERVER-93876): Remove.
         "//src/mongo/db:service_context",  # TODO(SERVER-93876): Remove.

src/mongo/db/curop.cpp

@@ -80,6 +80,7 @@
 #include "mongo/transport/service_executor.h"
 #include "mongo/util/assert_util.h"
 #include "mongo/util/clock_source.h"
+#include "mongo/util/concurrency/ticketholder_queue_stats.h"
 #include "mongo/util/database_name_util.h"
 #include "mongo/util/decorable.h"
 #include "mongo/util/duration.h"
@@ -97,7 +98,6 @@
 namespace mongo {
 
 namespace {
-StringMap<std::function<AdmissionContext*(OperationContext*)>> gQueueMetricsRegistry;
 
 auto& oplogGetMoreStats = *MetricBuilder<TimerStats>("repl.network.oplogGetMoresProcessed");
 
@@ -115,15 +115,6 @@ BSONObj serializeDollarDbInOpDescription(boost::optional<TenantId> tenantId,
                                          .firstElement());
     return newCmdObj;
 }
-
-MONGO_INITIALIZER(InitGlobalQueueLookupTable)(InitializerContext*) {
-    gQueueMetricsRegistry["ingress"] = [](OperationContext* opCtx) {
-        return &IngressAdmissionContext::get(opCtx);
-    };
-    gQueueMetricsRegistry["execution"] = [](OperationContext* opCtx) {
-        return &ExecutionAdmissionContext::get(opCtx);
-    };
-}
 }  // namespace
 
 /**
@@ -827,6 +818,47 @@ void appendObjectTruncatingAsNecessary(StringData fieldName,
     buildTruncatedObject(obj, *maxSize, builder);
     truncatedBuilder.doneFast();
 }
+
+/**
+ * Populates the BSONObjBuilder with the queueing statistics of the current operation. Calculates
+ * overall queue stats and records the current queue if the operation is presently queued.
+ */
+void populateCurrentOpQueueStats(OperationContext* opCtx,
+                                 TickSource* tickSource,
+                                 BSONObjBuilder* currOpStats) {
+    boost::optional<std::tuple<TicketHolderQueueStats::QueueType, Microseconds>> currentQueue;
+    BSONObjBuilder queuesBuilder(currOpStats->subobjStart("queues"));
+
+    for (auto&& [queueType, lookup] : TicketHolderQueueStats::getQueueMetricsRegistry()) {
+        AdmissionContext* admCtx = lookup(opCtx);
+        Microseconds totalTimeQueuedMicros = admCtx->totalTimeQueuedMicros();
+
+        if (auto startQueueingTime = admCtx->startQueueingTime()) {
+            Microseconds currentQueueTimeQueuedMicros = tickSource->ticksTo<Microseconds>(
+                opCtx->getServiceContext()->getTickSource()->getTicks() - *startQueueingTime);
+            totalTimeQueuedMicros += currentQueueTimeQueuedMicros;
+            currentQueue = std::make_tuple(queueType, currentQueueTimeQueuedMicros);
+        }
+        BSONObjBuilder queueMetricsBuilder(
+            queuesBuilder.subobjStart(TicketHolderQueueStats::queueTypeToString(queueType)));
+        queueMetricsBuilder.append("admissions", admCtx->getAdmissions());
+        queueMetricsBuilder.append("totalTimeQueuedMicros",
+                                   durationCount<Microseconds>(totalTimeQueuedMicros));
+        queueMetricsBuilder.append("isHoldingTicket", admCtx->isHoldingTicket());
+        queueMetricsBuilder.done();
+    }
+    queuesBuilder.done();
+    if (currentQueue) {
+        BSONObjBuilder currentQueueBuilder(currOpStats->subobjStart("currentQueue"));
+        currentQueueBuilder.append(
+            "name", TicketHolderQueueStats::queueTypeToString(std::get<0>(*currentQueue)));
+        currentQueueBuilder.append("timeQueuedMicros",
+                                   durationCount<Microseconds>(std::get<1>(*currentQueue)));
+        currentQueueBuilder.done();
+    } else {
+        currOpStats->appendNull("currentQueue");
+    }
+};
 }  // namespace
 
 BSONObj CurOp::truncateAndSerializeGenericCursor(GenericCursor cursor,
@@ -972,38 +1004,7 @@ void CurOp::reportState(BSONObjBuilder* builder,
         builder->append("waitForWriteConcernDurationMillis",
                         durationCount<Milliseconds>(elapsedTimeTotal));
     }
-
-    boost::optional<std::tuple<std::string, Microseconds>> currentQueue;
-    BSONObjBuilder queuesBuilder(builder->subobjStart("queues"));
-    for (auto&& [queueName, lookup] : gQueueMetricsRegistry) {
-        AdmissionContext* admCtx = lookup(opCtx);
-        Microseconds totalTimeQueuedMicros = admCtx->totalTimeQueuedMicros();
-
-        if (auto startQueueingTime = admCtx->startQueueingTime()) {
-            Microseconds currentQueueTimeQueuedMicros = computeElapsedTimeTotal(
-                *startQueueingTime, opCtx->getServiceContext()->getTickSource()->getTicks());
-            totalTimeQueuedMicros += currentQueueTimeQueuedMicros;
-            currentQueue = std::make_tuple(queueName, currentQueueTimeQueuedMicros);
-        }
-
-        BSONObjBuilder queueMetricsBuilder(queuesBuilder.subobjStart(queueName));
-        queueMetricsBuilder.append("admissions", admCtx->getAdmissions());
-        queueMetricsBuilder.append("totalTimeQueuedMicros",
-                                   durationCount<Microseconds>(totalTimeQueuedMicros));
-        queueMetricsBuilder.append("isHoldingTicket", admCtx->isHoldingTicket());
-        queueMetricsBuilder.done();
-    }
-    queuesBuilder.done();
-
-    if (currentQueue) {
-        BSONObjBuilder currentQueueBuilder(builder->subobjStart("currentQueue"));
-        currentQueueBuilder.append("name", std::get<0>(*currentQueue));
-        currentQueueBuilder.append("timeQueuedMicros",
-                                   durationCount<Microseconds>(std::get<1>(*currentQueue)));
-        currentQueueBuilder.done();
-    } else {
-        builder->appendNull("currentQueue");
-    }
+    populateCurrentOpQueueStats(opCtx, _tickSource, builder);
 }
 
 CurOp::AdditiveResourceStats CurOp::getAdditiveResourceStats(
@@ -1329,21 +1330,9 @@ void OpDebug::report(OperationContext* opCtx,
         pAttrs->add("remoteOpWaitMillis", durationCount<Milliseconds>(*remoteOpWaitTime));
     }
 
-    BSONObjBuilder queuesBuilder;
-    for (auto&& [queueName, lookup] : gQueueMetricsRegistry) {
-        AdmissionContext* admCtx = lookup(opCtx);
-        BSONObjBuilder bb;
-        if (auto admissions = admCtx->getAdmissions(); admissions > 0) {
-            bb.append("admissions", admissions);
-        }
-        if (auto queued = durationCount<Microseconds>(admCtx->totalTimeQueuedMicros());
-            queued > 0) {
-            bb.append("totalTimeQueuedMicros", queued);
-        }
-        queuesBuilder.append(queueName, bb.obj());
-    }
-
-    pAttrs->add("queues", queuesBuilder.obj());
+    // Extract admisson and execution control queueing stats from AdmissionContext stored on opCtx
+    TicketHolderQueueStats queueingStats(opCtx);
+    pAttrs->add("queues", queueingStats.toBson());
 
     // workingMillis should always be present for any operation
     pAttrs->add("workingMillis", workingTimeMillis.count());

src/mongo/db/curop_stats_test.cpp

@@ -27,11 +27,14 @@
  *    it in the license file.
  */
 
+#include "mongo/db/admission/execution_admission_context.h"
+#include "mongo/db/admission/ingress_admission_context.h"
 #include "mongo/db/curop.h"
 #include "mongo/db/prepare_conflict_tracker.h"
 #include "mongo/db/service_context_test_fixture.h"
 #include "mongo/db/transaction_resources.h"
 #include "mongo/unittest/assert.h"
+#include "mongo/unittest/bson_test_util.h"
 #include "mongo/unittest/framework.h"
 #include "mongo/util/tick_source_mock.h"
 namespace mongo {
@@ -80,7 +83,7 @@ int64_t addWaitForLock(OperationContext* opCtx,
     return stats.get(resId, MODE_S).combinedWaitTimeMicros;
 }
 
-void addTicketQueueTime(ExecutionAdmissionContext* admCtx,
+void addTicketQueueTime(AdmissionContext* admCtx,
                         TickSourceMock<Microseconds>* tickSource,
                         Milliseconds& executionTime,
                         Milliseconds waitForTickets) {
@@ -438,5 +441,58 @@ TEST_F(CurOpStatsTest, SubOperationStats) {
               executionTime2 - waitForTickets2 - waitForFlowControlTicket2 - waitForLocks2);
 }
 
+TEST_F(CurOpStatsTest, CheckAdmissionQueueStats) {
+    auto opCtx = makeOperationContext();
+    auto curop = CurOp::get(*opCtx);
+
+    Milliseconds waitForIngressAdmission = Milliseconds(2);
+    auto* ingressAdmCtx = &IngressAdmissionContext::get(opCtx.get());
+    ingressAdmCtx->setAdmission_forTest(5);
+
+    Milliseconds waitForExecutionTicket = Milliseconds(5);
+    auto* executionAdmCtx = &ExecutionAdmissionContext::get(opCtx.get());
+    executionAdmCtx->setAdmission_forTest(7);
+
+    // initialize timer to non-zero value
+    advanceTime(Milliseconds{100});
+    curop->setTickSource_forTest(tickSource());
+
+    Milliseconds executionTime = Milliseconds(512);
+    advanceTime(executionTime);
+    curop->done();
+
+    // Add queueing time for ingress admission control
+    addTicketQueueTime(ingressAdmCtx, tickSource(), executionTime, waitForIngressAdmission);
+
+    BSONObjBuilder builder;
+    SerializationContext sc = SerializationContext::stateCommandReply();
+    sc.setPrefixState(false);
+    {
+        // Simulate operation currently waiting in execution control queue
+        WaitingForAdmissionGuard waitForAdmission(executionAdmCtx, tickSource());
+        tickSource()->advance(waitForExecutionTicket);
+        executionTime += waitForExecutionTicket;
+
+        stdx::lock_guard<Client> lk(*opCtx->getClient());
+        curop->reportState(&builder, sc);
+    }
+    auto bsonObj = builder.done();
+    BSONObj currentQueue = bsonObj.getObjectField("currentQueue");
+    BSONObj queueStats = bsonObj.getObjectField("queues");
+
+    auto expectedCurrentQueue = BSON("name"
+                                     << "execution"
+                                     << "timeQueuedMicros" << 5000);
+    auto expectedQueueStats =
+        BSON("execution" << BSON("admissions" << 7 << "totalTimeQueuedMicros" << 5000
+                                              << "isHoldingTicket" << false)
+                         << "ingress"
+                         << BSON("admissions" << 5 << "totalTimeQueuedMicros" << 2000
+                                              << "isHoldingTicket" << false));
+
+    ASSERT_BSONOBJ_EQ(currentQueue, expectedCurrentQueue);
+    ASSERT_BSONOBJ_EQ_UNORDERED(queueStats, expectedQueueStats);
+}
+
 }  // namespace
 }  // namespace mongo

src/mongo/db/stats/BUILD.bazel

@@ -133,6 +133,7 @@ mongo_cc_library(
     deps = [
         "//src/mongo/db:server_base",
         "//src/mongo/db/repl:read_concern_args",
+        "//src/mongo/util/concurrency:ticketholder_queue_stats",
     ],
 )
 

src/mongo/db/stats/single_transaction_stats.h

@@ -41,9 +41,11 @@
 #include "mongo/bson/timestamp.h"
 #include "mongo/db/client.h"
 #include "mongo/db/curop.h"
+#include "mongo/db/operation_context.h"
 #include "mongo/db/repl/read_concern_args.h"
 #include "mongo/db/session/logical_session_id.h"
 #include "mongo/rpc/metadata/client_metadata.h"
+#include "mongo/util/concurrency/ticketholder_queue_stats.h"
 #include "mongo/util/duration.h"
 #include "mongo/util/net/hostandport.h"
 #include "mongo/util/tick_source.h"
@@ -210,6 +212,21 @@ class SingleTransactionStats {
         _lastClientInfo.update(client);
     }
 
+
+    /**
+     * Returns the TicketHolderQueueStats object stored in this SingleTransactionStats.
+     */
+    const TicketHolderQueueStats& getQueueStats() const {
+        return _queueStats;
+    }
+    /**
+     * Updates the TicketHolderQueueStats to include the latest operation's queueing stats.
+     */
+    void updateQueueStats(OperationContext* opCtx) {
+        TicketHolderQueueStats newOpQueueStat(opCtx);
+        _queueStats.add(newOpQueueStat);
+    }
+
     /**
      * Set the autoCommit field.  If this field is unset, this is not a transaction but a
      * retryable write and other values will not be meaningful.
@@ -286,6 +303,10 @@ class SingleTransactionStats {
     // not be set in a transaction that is in state kPrepared if an exception is thrown after the
     // transaction transitions to the prepared state but before setPreparedStartTime is called.
     boost::optional<TickSource::Tick> _preparedStartTime{boost::none};
+
+    // Tracks and aggregates statistics for admission and execution control queueing across all
+    // operations within a transaction.
+    TicketHolderQueueStats _queueStats;
 };
 
 }  // namespace mongo

src/mongo/db/transaction/transaction_metrics_observer.cpp

@@ -212,6 +212,9 @@ void TransactionMetricsObserver::onTransactionOperation(OperationContext* opCtx,
     // TransactionMetricsObserver with this Client's information. This is the last client that ran a
     // transaction operation on the txnParticipant.
     _singleTransactionStats.updateLastClientInfo(opCtx->getClient());
+
+    // Update TicketHolderQueueStats with the latest operation's queueing data.
+    _singleTransactionStats.updateQueueStats(opCtx);
 }
 
 void TransactionMetricsObserver::_onAbort(OperationContext* opCtx,

src/mongo/db/transaction/transaction_participant.cpp

@@ -2883,6 +2883,8 @@ std::string TransactionParticipant::Participant::_transactionInfoForLog(
         s << " prepareOpTime:" << o().prepareOpTime.toString();
     }
 
+    s << " queues:" << singleTransactionStats.getQueueStats().toBson().toString();
+
     // Total duration of the transaction.
     s << ", "
       << duration_cast<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick));
@@ -2955,6 +2957,8 @@ void TransactionParticipant::Participant::_transactionInfoForLog(
         pAttrs->add("prepareOpTime", o().prepareOpTime);
     }
 
+    pAttrs->add("queues", singleTransactionStats.getQueueStats().toBson());
+
     // Total duration of the transaction.
     pAttrs->add(
         "duration",
@@ -3031,6 +3035,8 @@ BSONObj TransactionParticipant::Participant::_transactionInfoBSONForLog(
             attrs.append("prepareOpTime", o().prepareOpTime.toBSON());
         }
 
+        attrs.append("queues", singleTransactionStats.getQueueStats().toBson());
+
         // Total duration of the transaction.
         attrs.append(
             "durationMillis",