SERVER-40985 Basic slow transaction logging on mongos

1 files changed, 136 insertions, 3 deletions

diff --git a/src/mongo/s/transaction_router.h b/src/mongo/s/transaction_router.h
index 1cd3cd0dac7..4d38a52562d 100644
--- a/src/mongo/s/transaction_router.h
+++ b/src/mongo/s/transaction_router.h
@@ -95,8 +95,40 @@ public:
         const SharedTransactionOptions sharedOptions;
     };
 
+    // Container for timing stats for the current transaction. Includes helpers for calculating some
+    // metrics like transaction duration.
+    struct TimingStats {
+        /**
+         * Returns the duration of the transaction. The transaction start time must have been set
+         * before this can be called.
+         */
+        Microseconds getDuration(TickSource* tickSource, TickSource::Tick curTicks) const;
+
+        /**
+         * Returns the duration of commit. The commit start time must have been set before this can
+         * be called.
+         */
+        Microseconds getCommitDuration(TickSource* tickSource, TickSource::Tick curTicks) const;
+
+        // The start time of the transaction. Note that tick values should only ever be used to
+        // measure distance from other tick values, not for reporting absolute wall clock time.
+        TickSource::Tick startTime{0};
+
+        // When commit was started.
+        TickSource::Tick commitStartTime{0};
+
+        // The end time of the transaction.
+        TickSource::Tick endTime{0};
+    };
+
     enum class TransactionActions { kStart, kContinue, kCommit };
 
+    // Reason a transaction terminated.
+    enum class TerminationCause {
+        kCommitted,
+        kAborted,
+    };
+
     /**
      * Encapsulates the logic around selecting a global read timestamp for a sharded transaction at
      * snapshot level read concern.
@@ -287,15 +319,57 @@ public:
         return _latestStmtId;
     }
 
+    /**
+     * Returns a copy of the timing stats of the transaction router's active transaction.
+     */
+    TimingStats getTimingStats() const {
+        return _timingStats;
+    }
+
 private:
     // The type of commit initiated for this transaction.
     enum class CommitType {
         kNotInitiated,
-        kDirectCommit,
+        kNoShards,
+        kSingleShard,
+        kSingleWriteShard,
+        kReadOnly,
         kTwoPhaseCommit,
         kRecoverWithToken,
     };
 
+    // Helper to convert the CommitType enum into a human readable string for diagnostics.
+    std::string _commitTypeToString(CommitType state) const {
+        switch (state) {
+            case CommitType::kNotInitiated:
+                return "notInitiated";
+            case CommitType::kNoShards:
+                return "noShards";
+            case CommitType::kSingleShard:
+                return "singleShard";
+            case CommitType::kSingleWriteShard:
+                return "singleWriteShard";
+            case CommitType::kReadOnly:
+                return "readOnly";
+            case CommitType::kTwoPhaseCommit:
+                return "twoPhaseCommit";
+            case CommitType::kRecoverWithToken:
+                return "recoverWithToken";
+        }
+        MONGO_UNREACHABLE;
+    }
+
+    /**
+     * Prints slow transaction information to the log.
+     */
+    void _logSlowTransaction(OperationContext* opCtx, TerminationCause terminationCause) const;
+
+    /**
+     * Returns a string to be logged for slow transactions.
+     */
+    std::string _transactionInfoForLog(OperationContext* opCtx,
+                                       TerminationCause terminationCause) const;
+
     // Shortcut to obtain the id of the session under which this transaction router runs
     const LogicalSessionId& _sessionId() const;
 
@@ -307,6 +381,12 @@ private:
     void _resetRouterState(const TxnNumber& txnNumber);
 
     /**
+     * Internal method for committing a transaction. Should only throw on failure to send commit.
+     */
+    BSONObj _commitTransaction(OperationContext* opCtx,
+                               const boost::optional<TxnRecoveryToken>& recoveryToken);
+
+    /**
      * Retrieves the transaction's outcome from the shard specified in the recovery token.
      */
     BSONObj _commitWithRecoveryToken(OperationContext* opCtx,
@@ -353,12 +433,58 @@ private:
      */
     void _verifyParticipantAtClusterTime(const Participant& participant);
 
+    /**
+     * Updates relevant metrics when a new transaction is begun.
+     */
+    void _onNewTransaction(OperationContext* opCtx);
+
+    /**
+     * Updates relevant metrics when a router receives commit for a higher txnNumber than it has
+     * seen so far.
+     */
+    void _onBeginRecoveringDecision(OperationContext* opCtx);
+
+    /**
+     * Updates relevant metrics when the router receives an explicit abort from the client.
+     */
+    void _onExplicitAbort(OperationContext* opCtx);
+
+    /**
+     * Updates relevant metrics when the router begins an implicit abort after an error.
+     */
+    void _onImplicitAbort(OperationContext* opCtx, const Status& errorStatus);
+
+    /**
+     * Updates relevant metrics when a transaction is about to begin commit.
+     */
+    void _onStartCommit(OperationContext* opCtx);
+
+    /**
+     * Updates relevant metrics when a transaction receives a successful response for commit.
+     */
+    void _onSuccessfulCommit(OperationContext* opCtx);
+
+    /**
+     * Updates relevant metrics when commit receives a response with a non-retryable command error
+     * per the retryable writes specification.
+     */
+    void _onNonRetryableCommitError(OperationContext* opCtx, Status commitStatus);
+
+    /**
+     * The first time this method is called it marks the transaction as over in the router's
+     * diagnostics and will log transaction information if its duration is over the global slowMS
+     * threshold or the transaction log componenet verbosity >= 1. Only meant to be called when the
+     * router definitively knows the transaction's outcome, e.g. it should not be invoked after a
+     * network error on commit.
+     */
+    void _endTransactionTrackingIfNecessary(OperationContext* opCtx,
+                                            TerminationCause terminationCause);
+
     // The currently active transaction number on this router, if beginOrContinueTxn has been
     // called. Otherwise set to kUninitializedTxnNumber.
     TxnNumber _txnNumber{kUninitializedTxnNumber};
 
-    // Is updated at commit time to reflect whether the direct commit, two-phase commit, or recover
-    // commit path was taken.
+    // Is updated at commit time to reflect which commit path was taken.
     CommitType _commitType{CommitType::kNotInitiated};
 
     // Indicates whether this is trying to recover a commitTransaction on the current transaction.
@@ -396,6 +522,13 @@ private:
     // The statement id of the command that began this transaction. Defaults to zero if no statement
     // id was included in the first command.
     StmtId _firstStmtId{kDefaultFirstStmtId};
+
+    // String representing the reason a transaction aborted. Either the string name of the error
+    // code that led to an implicit abort or "abort" if the client sent abortTransaction.
+    std::string _abortCause;
+
+    // Stats used for calculating durations for the active transaction.
+    TimingStats _timingStats;
 };
 
 }  // namespace mongo