diff options
author | Nathan Louie <nathan.louie@10gen.com> | 2018-08-16 16:17:59 -0400 |
---|---|---|
committer | jinichu <jinnybyun@gmail.com> | 2018-08-16 16:17:59 -0400 |
commit | bfa31257c2f5323e3bf80ffa3c3b870bdd83cb2a (patch) | |
tree | 144c1d7a671781f91d523134daa9b10929fea7c9 | |
parent | 19557f15faed29927ee770b6bbf3180fbfff24b7 (diff) | |
download | mongo-bfa31257c2f5323e3bf80ffa3c3b870bdd83cb2a.tar.gz |
SERVER-35432 Add a method for printing out information about a slow transaction
(cherry picked from commit cdc82971d30cbac5115c532e8d296ba74aebb204)
-rw-r--r-- | src/mongo/db/curop.cpp | 18 | ||||
-rw-r--r-- | src/mongo/db/curop.h | 7 | ||||
-rw-r--r-- | src/mongo/db/session.cpp | 48 | ||||
-rw-r--r-- | src/mongo/db/session.h | 13 | ||||
-rw-r--r-- | src/mongo/db/session_test.cpp | 203 |
5 files changed, 289 insertions, 0 deletions
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index 91ea98bd4f8..e7dc7460efa 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -780,4 +780,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 c4944529cfb..cdb37d6cc8a 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 84c1d869a4a..80663b88a55 100644 --- a/src/mongo/db/session.cpp +++ b/src/mongo/db/session.cpp @@ -1158,6 +1158,54 @@ void Session::_reportTransactionStats(WithLock wl, } } +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 bdedd2fff5f..7cbfcff92f7 100644 --- a/src/mongo/db/session.h +++ b/src/mongo/db/session.h @@ -329,6 +329,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. @@ -348,6 +353,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 73106d6c05e..ec5175cbdf1 100644 --- a/src/mongo/db/session_test.cpp +++ b/src/mongo/db/session_test.cpp @@ -42,6 +42,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" @@ -2244,5 +2245,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(¶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<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 |