SERVER-35432 Add a method for printing out information about a slow transaction

5 files changed, 289 insertions, 0 deletions

diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index df504a19ca2..e6bc3462528 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -774,4 +774,22 @@ void OpDebug::AdditiveMetrics::incrementPrepareReadConflicts(long long n) {
     *prepareReadConflicts += n;
 }
 
+string OpDebug::AdditiveMetrics::report() {
+    StringBuilder s;
+
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("keysExamined", keysExamined);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("docsExamined", docsExamined);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("nMatched", nMatched);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("nModified", nModified);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("ninserted", ninserted);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("ndeleted", ndeleted);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("nmoved", nmoved);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("keysInserted", keysInserted);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("keysDeleted", keysDeleted);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("prepareReadConflicts", prepareReadConflicts);
+    OPDEBUG_TOSTRING_HELP_OPTIONAL("writeConflicts", writeConflicts);
+
+    return s.str();
+}
+
 }  // namespace mongo
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index e5270756c0c..52b03ac7db2 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -98,6 +98,13 @@ public:
          */
         void incrementPrepareReadConflicts(long long n);
 
+        /**
+         * Generates a string showing all non-empty fields. For every non-empty field field1,
+         * field2, ..., with corresponding values value1, value2, ..., we will output a string in
+         * the format: "<field1>:<value1> <field2>:<value2> ...".
+         */
+        std::string report();
+
         boost::optional<long long> keysExamined;
         boost::optional<long long> docsExamined;
 
diff --git a/src/mongo/db/session.cpp b/src/mongo/db/session.cpp
index b4a5d496f05..064c2810a40 100644
--- a/src/mongo/db/session.cpp
+++ b/src/mongo/db/session.cpp
@@ -1201,6 +1201,54 @@ void Session::_reportTransactionStats(WithLock wl, BSONObjBuilder* builder) cons
     builder->append("timeInactiveMicros", timeInactive);
 }
 
+std::string Session::transactionInfoForLog(const SingleThreadedLockStats* lockStats) {
+    // Need to lock because this function checks the state of _txnState.
+    stdx::lock_guard<stdx::mutex> lg(_mutex);
+
+    invariant(lockStats);
+    invariant(_txnState.isCommitted(lg) || _txnState.isAborted(lg));
+
+    StringBuilder s;
+
+    // User specified transaction parameters.
+    BSONObjBuilder parametersBuilder;
+    BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid"));
+    _sessionId.serialize(&lsidBuilder);
+    lsidBuilder.doneFast();
+    parametersBuilder.append("txnNumber", _activeTxnNumber);
+    // TODO: SERVER-35174 Add readConcern to parameters here once pushed.
+    parametersBuilder.append("autocommit", _autocommit);
+    s << "parameters:" << parametersBuilder.obj().toString() << ",";
+
+    s << " readTimestamp:" << _speculativeTransactionReadOpTime.getTimestamp().toString() << ",";
+
+    s << _singleTransactionStats->getOpDebug()->additiveMetrics.report();
+
+    std::string terminationCause = _txnState.isCommitted(lg) ? "committed" : "aborted";
+    s << " terminationCause:" << terminationCause;
+
+    auto curTime = curTimeMicros64();
+    s << " timeActiveMicros:"
+      << durationCount<Microseconds>(_singleTransactionStats->getTimeActiveMicros(curTime));
+    s << " timeInactiveMicros:"
+      << durationCount<Microseconds>(_singleTransactionStats->getTimeInactiveMicros(curTime));
+
+    // Number of yields is always 0 in multi-document transactions, but it is included mainly to
+    // match the format with other slow operation logging messages.
+    s << " numYields:" << 0;
+
+    // Aggregate lock statistics.
+    BSONObjBuilder locks;
+    lockStats->report(&locks);
+    s << " locks:" << locks.obj().toString();
+
+    // Total duration of the transaction.
+    s << " "
+      << Milliseconds{static_cast<long long>(_singleTransactionStats->getDuration(curTime)) / 1000};
+
+    return s.str();
+}
+
 void Session::_checkValid(WithLock) const {
     uassert(ErrorCodes::ConflictingOperationInProgress,
             str::stream() << "Session " << getSessionId()
diff --git a/src/mongo/db/session.h b/src/mongo/db/session.h
index 51c4ad71370..6f5cf1d0243 100644
--- a/src/mongo/db/session.h
+++ b/src/mongo/db/session.h
@@ -358,6 +358,11 @@ public:
         return _singleTransactionStats;
     }
 
+    repl::OpTime getSpeculativeTransactionReadOpTimeForTest() const {
+        stdx::lock_guard<stdx::mutex> lk(_mutex);
+        return _speculativeTransactionReadOpTime;
+    }
+
     /**
      * If this session is holding stashed locks in _txnResourceStash, reports the current state of
      * the session using the provided builder. Locks the session object's mutex while running.
@@ -377,6 +382,14 @@ public:
      */
     BSONObj reportStashedState() const;
 
+    /**
+     * This method returns a string with information about a slow transaction. The format of the
+     * logging string produced should match the format used for slow operation logging. A
+     * transaction must be completed (committed or aborted) and a valid LockStats reference must be
+     * passed in order for this method to be called.
+     */
+    std::string transactionInfoForLog(const SingleThreadedLockStats* lockStats);
+
     void addMultikeyPathInfo(MultikeyPathInfo info) {
         _multikeyPathInfo.push_back(std::move(info));
     }
diff --git a/src/mongo/db/session_test.cpp b/src/mongo/db/session_test.cpp
index 0cd00d580dd..33bb9a957f7 100644
--- a/src/mongo/db/session_test.cpp
+++ b/src/mongo/db/session_test.cpp
@@ -44,6 +44,7 @@
 #include "mongo/db/stats/fill_locker_info.h"
 #include "mongo/stdx/future.h"
 #include "mongo/stdx/memory.h"
+#include "mongo/unittest/death_test.h"
 #include "mongo/unittest/unittest.h"
 #include "mongo/util/net/socket_utils.h"
 
@@ -2711,5 +2712,207 @@ TEST_F(TransactionsMetricsTest, LastClientInfoShouldUpdateUponAbort) {
                       obj.getField("client").Obj());
 }
 
+namespace {
+
+/*
+ * Sets up the additive metrics for Transactions Metrics test.
+ */
+void setupAdditiveMetrics(const int metricValue, OperationContext* opCtx) {
+    CurOp::get(opCtx)->debug().additiveMetrics.keysExamined = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.docsExamined = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.nMatched = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.nModified = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.ninserted = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.ndeleted = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.nmoved = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.keysInserted = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.keysDeleted = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.prepareReadConflicts = metricValue;
+    CurOp::get(opCtx)->debug().additiveMetrics.writeConflicts = metricValue;
+}
+
+/*
+ * Builds expected parameters info string.
+ */
+void buildParametersInfoString(StringBuilder* sb,
+                               LogicalSessionId sessionId,
+                               const TxnNumber txnNum) {
+    BSONObjBuilder lsidBuilder;
+    sessionId.serialize(&lsidBuilder);
+    (*sb) << "parameters:{ lsid: " << lsidBuilder.done().toString() << ", txnNumber: " << txnNum
+          << ", autocommit: false },";
+}
+
+/*
+ * Builds expected single transaction stats info string.
+ */
+void buildSingleTransactionStatsString(StringBuilder* sb, const int metricValue) {
+    (*sb) << " keysExamined:" << metricValue << " docsExamined:" << metricValue
+          << " nMatched:" << metricValue << " nModified:" << metricValue
+          << " ninserted:" << metricValue << " ndeleted:" << metricValue
+          << " nmoved:" << metricValue << " keysInserted:" << metricValue
+          << " keysDeleted:" << metricValue << " prepareReadConflicts:" << metricValue
+          << " writeConflicts:" << metricValue;
+}
+
+/*
+ * Builds the time active and time inactive info string.
+ */
+void buildTimeActiveInactiveString(StringBuilder* sb,
+                                   Session* session,
+                                   unsigned long long curTime) {
+    // Add time active micros to string.
+    (*sb) << " timeActiveMicros:"
+          << durationCount<Microseconds>(
+                 session->getSingleTransactionStats()->getTimeActiveMicros(curTime));
+
+    // Add time inactive micros to string.
+    (*sb) << " timeInactiveMicros:"
+          << session->getSingleTransactionStats()->getDuration(curTime) -
+            durationCount<Microseconds>(
+                 session->getSingleTransactionStats()->getTimeActiveMicros(curTime));
+}
+
+
+/*
+ * Builds the entire expected transaction info string and returns it.
+ */
+std::string buildTransactionInfoString(OperationContext* opCtx,
+                                       Session* session,
+                                       std::string terminationCause,
+                                       const LogicalSessionId sessionId,
+                                       const TxnNumber txnNum,
+                                       const int metricValue) {
+    // Calling transactionInfoForLog to get the actual transaction info string.
+    const auto lockerInfo = opCtx->lockState()->getLockerInfo();
+
+    // Building expected transaction info string.
+    StringBuilder parametersInfo;
+    buildParametersInfoString(&parametersInfo, sessionId, txnNum);
+
+    StringBuilder readTimestampInfo;
+    readTimestampInfo
+        << " readTimestamp:"
+        << session->getSpeculativeTransactionReadOpTimeForTest().getTimestamp().toString() << ",";
+
+    StringBuilder singleTransactionStatsInfo;
+    buildSingleTransactionStatsString(&singleTransactionStatsInfo, metricValue);
+
+    auto curTime = curTimeMicros64();
+    StringBuilder timeActiveAndInactiveInfo;
+    buildTimeActiveInactiveString(&timeActiveAndInactiveInfo, session, curTime);
+
+    BSONObjBuilder locks;
+    if (lockerInfo) {
+        lockerInfo->stats.report(&locks);
+    }
+
+    // Puts all the substrings together into one expected info string. The expected info string will
+    // look something like this:
+    // parameters:{ lsid: { id: UUID("f825288c-100e-49a1-9fd7-b95c108049e6"), uid: BinData(0,
+    // E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) }, txnNumber: 1,
+    // autocommit: false }, readTimestamp:Timestamp(0, 0), keysExamined:1 docsExamined:1 nMatched:1
+    // nModified:1 ninserted:1 ndeleted:1 nmoved:1 keysInserted:1 keysDeleted:1
+    // prepareReadConflicts:1 writeConflicts:1 terminationCause:committed timeActiveMicros:3
+    // timeInactiveMicros:2 numYields:0 locks:{ Global: { acquireCount: { r: 6, w: 4 } }, Database:
+    // { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { R: 1 } }, oplog: {
+    // acquireCount: { W: 1 } } } 0ms
+    StringBuilder expectedTransactionInfo;
+    expectedTransactionInfo << parametersInfo.str() << readTimestampInfo.str()
+                            << singleTransactionStatsInfo.str()
+                            << " terminationCause:" << terminationCause
+                            << timeActiveAndInactiveInfo.str() << " numYields:" << 0
+                            << " locks:" << locks.done().toString() << " "
+                            << Milliseconds{
+                                   static_cast<long long>(
+                                       session->getSingleTransactionStats()->getDuration(curTime)) /
+                                   1000};
+    return expectedTransactionInfo.str();
+}
+}  // namespace
+
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterCommit) {
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "commitTransaction");
+
+    // Initialize SingleTransactionStats AdditiveMetrics objects.
+    const int metricValue = 1;
+    setupAdditiveMetrics(metricValue, opCtx());
+
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+    session.commitTransaction(opCtx(), boost::none);
+
+    const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
+    ASSERT(lockerInfo);
+    std::string testTransactionInfo = session.transactionInfoForLog(&lockerInfo->stats);
+
+    std::string expectedTransactionInfo =
+        buildTransactionInfoString(opCtx(), &session, "committed", sessionId, txnNum, metricValue);
+    ASSERT_EQ(testTransactionInfo, expectedTransactionInfo);
+}
+
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterAbort) {
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "abortTransaction");
+
+    // Initialize SingleTransactionStats AdditiveMetrics objects.
+    const int metricValue = 1;
+    setupAdditiveMetrics(metricValue, opCtx());
+
+    session.unstashTransactionResources(opCtx(), "abortTransaction");
+    session.abortActiveTransaction(opCtx());
+
+    const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
+    ASSERT(lockerInfo);
+    std::string testTransactionInfo = session.transactionInfoForLog(&lockerInfo->stats);
+
+    std::string expectedTransactionInfo =
+        buildTransactionInfoString(opCtx(), &session, "aborted", sessionId, txnNum, metricValue);
+    ASSERT_EQ(testTransactionInfo, expectedTransactionInfo);
+}
+
+DEATH_TEST_F(TransactionsMetricsTest, UnterminatedLogTransactionInfoFails, "invariant") {
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+
+    const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
+    ASSERT(lockerInfo);
+    session.transactionInfoForLog(&lockerInfo->stats);
+}
+
+DEATH_TEST_F(TransactionsMetricsTest, noLockerInfoStatsFails, "invariant") {
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+    session.commitTransaction(opCtx(), boost::none);
+
+    session.transactionInfoForLog(nullptr);
+}
+
 }  // namespace
 }  // namespace mongo