From cdc82971d30cbac5115c532e8d296ba74aebb204 Mon Sep 17 00:00:00 2001 From: Nathan Louie Date: Mon, 9 Jul 2018 14:41:37 -0400 Subject: SERVER-35432 Add a method for printing out information about a slow transaction --- src/mongo/db/curop.cpp | 18 ++++ src/mongo/db/curop.h | 7 ++ src/mongo/db/session.cpp | 48 ++++++++++ src/mongo/db/session.h | 13 +++ src/mongo/db/session_test.cpp | 203 ++++++++++++++++++++++++++++++++++++++++++ 5 files changed, 289 insertions(+) (limited to 'src') 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: ": : ...". + */ + std::string report(); + boost::optional keysExamined; boost::optional 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 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(_singleTransactionStats->getTimeActiveMicros(curTime)); + s << " timeInactiveMicros:" + << durationCount(_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(_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 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( + session->getSingleTransactionStats()->getTimeActiveMicros(curTime)); + + // Add time inactive micros to string. + (*sb) << " timeInactiveMicros:" + << session->getSingleTransactionStats()->getDuration(curTime) - + durationCount( + 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(¶metersInfo, 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( + 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 -- cgit v1.2.1