diff options
author | Ian Boros <ian.boros@mongodb.com> | 2020-04-22 17:27:22 -0400 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2021-02-03 16:54:09 +0000 |
commit | 30ebef0be7a29c9f7f7630615419eaead7c071c5 (patch) | |
tree | 28b172c75736d5a646978b697afe75fbcfe3f75b | |
parent | fdf53c68a6eceb8d0dffeb8a48479cfd4d01861f (diff) | |
download | mongo-30ebef0be7a29c9f7f7630615419eaead7c071c5.tar.gz |
SERVER-47869 Add debug logging mechanism to mongos cursor manager
There is a bug in the mongos cursor manager tracked by SERVER-27796 which has never been reproduced
in our testing environment but has been encountered by multiple customers. This change adds a small
diagnostic log to the mongos cursor manager which is dumped when a symptom of the bug is found.
-rw-r--r-- | src/mongo/s/query/cluster_cursor_manager.cpp | 158 | ||||
-rw-r--r-- | src/mongo/s/query/cluster_cursor_manager.h | 91 |
2 files changed, 237 insertions, 12 deletions
diff --git a/src/mongo/s/query/cluster_cursor_manager.cpp b/src/mongo/s/query/cluster_cursor_manager.cpp index 98123e23118..5c267bde0a1 100644 --- a/src/mongo/s/query/cluster_cursor_manager.cpp +++ b/src/mongo/s/query/cluster_cursor_manager.cpp @@ -202,7 +202,8 @@ boost::optional<TxnNumber> ClusterCursorManager::PinnedCursor::getTxnNumber() co ClusterCursorManager::ClusterCursorManager(ClockSource* clockSource) : _clockSource(clockSource), - _pseudoRandom(std::unique_ptr<SecureRandom>(SecureRandom::create())->nextInt64()) { + _randomSeed(std::unique_ptr<SecureRandom>(SecureRandom::create())->nextInt64()), + _pseudoRandom(_randomSeed) { invariant(_clockSource); } @@ -230,7 +231,7 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor( const auto now = _clockSource->now(); stdx::unique_lock<stdx::mutex> lk(_mutex); - + _log.push({LogEvent::Type::kRegisterAttempt, boost::none, now, nss}); if (_inShutdown) { lk.unlock(); cursor->kill(opCtx); @@ -277,6 +278,7 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor( cursorId, CursorEntry(std::move(cursor), cursorType, cursorLifetime, now, authenticatedUsers)); invariant(emplaceResult.second); + _log.push({LogEvent::Type::kRegisterComplete, cursorId, now, nss}); return cursorId; } @@ -287,8 +289,9 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur OperationContext* opCtx, AuthzCheckFn authChecker, AuthCheck checkSessionAuth) { + const auto now = _clockSource->now(); stdx::lock_guard<stdx::mutex> lk(_mutex); - + _log.push({LogEvent::Type::kCheckoutAttempt, cursorId, now, nss}); if (_inShutdown) { return Status(ErrorCodes::ShutdownInProgress, "Cannot check out cursor as we are in the process of shutting down"); @@ -334,6 +337,7 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur } cursor->reattachToOperationContext(opCtx); + _log.push({LogEvent::Type::kCheckoutComplete, cursorId, now, nss}); return PinnedCursor(this, std::move(cursor), nss, cursorId); } @@ -351,6 +355,7 @@ void ClusterCursorManager::checkInCursor(std::unique_ptr<ClusterClientCursor> cu cursor->detachFromOperationContext(); stdx::unique_lock<stdx::mutex> lk(_mutex); + _log.push({LogEvent::Type::kCheckInAttempt, cursorId, now, nss}); CursorEntry* entry = _getEntry(lk, nss, cursorId); invariant(entry); @@ -362,6 +367,7 @@ void ClusterCursorManager::checkInCursor(std::unique_ptr<ClusterClientCursor> cu entry->returnCursor(std::move(cursor)); if (cursorState == CursorState::NotExhausted && !killPending) { + _log.push({LogEvent::Type::kCheckInCompleteCursorSaved, cursorId, now, nss}); // The caller may need the cursor again. return; } @@ -403,7 +409,9 @@ Status ClusterCursorManager::killCursor(OperationContext* opCtx, CursorId cursorId) { invariant(opCtx); + const auto now = _clockSource->now(); stdx::unique_lock<stdx::mutex> lk(_mutex); + _log.push({LogEvent::Type::kKillCursorAttempt, cursorId, now, nss}); CursorEntry* entry = _getEntry(lk, nss, cursorId); if (!entry) { @@ -442,8 +450,9 @@ void ClusterCursorManager::detachAndKillCursor(stdx::unique_lock<stdx::mutex> lk std::size_t ClusterCursorManager::killMortalCursorsInactiveSince(OperationContext* opCtx, Date_t cutoff) { - stdx::unique_lock<stdx::mutex> lk(_mutex); + const auto now = _clockSource->now(); + stdx::unique_lock<stdx::mutex> lk(_mutex); auto pred = [cutoff](CursorId cursorId, const CursorEntry& entry) -> bool { bool res = entry.getLifetimeType() == CursorLifetime::Mortal && !entry.getOperationUsingCursor() && entry.getLastActive() <= cutoff; @@ -456,24 +465,29 @@ std::size_t ClusterCursorManager::killMortalCursorsInactiveSince(OperationContex return res; }; - return killCursorsSatisfying(std::move(lk), opCtx, std::move(pred)); + return killCursorsSatisfying(std::move(lk), opCtx, std::move(pred), now); } void ClusterCursorManager::killAllCursors(OperationContext* opCtx) { + const auto now = _clockSource->now(); stdx::unique_lock<stdx::mutex> lk(_mutex); + auto pred = [](CursorId, const CursorEntry&) -> bool { return true; }; - killCursorsSatisfying(std::move(lk), opCtx, std::move(pred)); + killCursorsSatisfying(std::move(lk), opCtx, std::move(pred), now); } std::size_t ClusterCursorManager::killCursorsSatisfying( stdx::unique_lock<stdx::mutex> lk, OperationContext* opCtx, - std::function<bool(CursorId, const CursorEntry&)> pred) { + std::function<bool(CursorId, const CursorEntry&)> pred, + Date_t now) { invariant(opCtx); invariant(lk.owns_lock()); std::size_t nKilled = 0; + _log.push( + {LogEvent::Type::kRemoveCursorsSatisfyingPredicateAttempt, boost::none, now, boost::none}); std::vector<std::unique_ptr<ClusterClientCursor>> cursorsToDestroy; auto nsContainerIt = _namespaceToContainerMap.begin(); while (nsContainerIt != _namespaceToContainerMap.end()) { @@ -497,6 +511,13 @@ std::size_t ClusterCursorManager::killCursorsSatisfying( continue; } + _log.push({LogEvent::Type::kCursorMarkedForDeletionBySatisfyingPredicate, + cursorId, + // While we collected 'now' above, we ran caller-provided predicates which + // may have been expensive. To avoid re-reading from the clock while the + // lock is held, we do not provide a value for 'now' in this log entry. + boost::none, + nsContainerIt->first}); cursorsToDestroy.push_back(entry.releaseCursor(nullptr)); // Destroy the entry and set the iterator to the next element. @@ -510,6 +531,13 @@ std::size_t ClusterCursorManager::killCursorsSatisfying( } } + _log.push({LogEvent::Type::kRemoveCursorsSatisfyingPredicateComplete, + boost::none, + // While we collected 'now' above, we ran caller-provided predicates which may have + // been expensive. To avoid re-reading from the clock while the lock is held, we do + // not provide a value for 'now' in this log entry. + boost::none, + boost::none}); // Call kill() outside of the lock, as it may require waiting for callbacks to finish. lk.unlock(); @@ -672,15 +700,30 @@ auto ClusterCursorManager::eraseContainer(NssToCursorContainerMap::iterator it) // This was the last cursor remaining in the given namespace. Erase all state associated // with this namespace. size_t numDeleted = _cursorIdPrefixToNamespaceMap.erase(container.containerPrefix); - invariant(numDeleted == 1); - it = _namespaceToContainerMap.erase(it); + if (numDeleted != 1) { + LOG(0).setIsTruncatable(false) + << "Error attempting to erase CursorEntryContainer for nss " << it->first + << " and containerPrefix " << container.containerPrefix + << ". Could not find containerPrefix in map from cursor ID prefix to nss. Expected " + "'numDeleted' to be 1, but got " + << numDeleted; + logCursorManagerInfo(); + MONGO_UNREACHABLE; + } + const auto nssRemoved = it->first; + _namespaceToContainerMap.erase(it++); + _log.push({LogEvent::Type::kNamespaceEntryMapErased, + boost::none, + boost::none, + std::move(nssRemoved)}); + invariant(_namespaceToContainerMap.size() == _cursorIdPrefixToNamespaceMap.size()); return it; } StatusWith<std::unique_ptr<ClusterClientCursor>> ClusterCursorManager::_detachCursor( WithLock lk, NamespaceString const& nss, CursorId cursorId) { - + _log.push({LogEvent::Type::kDetachAttempt, cursorId, boost::none, nss}); CursorEntry* entry = _getEntry(lk, nss, cursorId); if (!entry) { return cursorNotFoundStatus(nss, cursorId); @@ -703,7 +746,102 @@ StatusWith<std::unique_ptr<ClusterClientCursor>> ClusterCursorManager::_detachCu eraseContainer(nsToContainerIt); } + _log.push({LogEvent::Type::kDetachComplete, cursorId, boost::none, nss}); + return std::move(cursor); } +void ClusterCursorManager::logCursorManagerInfo() const { + LOG(0).setIsTruncatable(false) << "Dumping cursor manager contents." + << " NSS -> Container map: " << dumpNssToContainerMap() + << " Cursor ID Prefix -> NSS map: " << dumpCursorIdToNssMap() + << " Internal log: " << dumpInternalLog(); +} + +std::string ClusterCursorManager::LogEvent::typeToString(ClusterCursorManager::LogEvent::Type t) { + static const std::map<LogEvent::Type, std::string> kMap = { + {Type::kRegisterAttempt, "registerAttempt"}, + {Type::kRegisterComplete, "registerComplete"}, + {Type::kCheckoutAttempt, "checkoutAttempt"}, + {Type::kCheckoutComplete, "checkoutComplete"}, + {Type::kCheckInAttempt, "checkInAttempt"}, + {Type::kCheckInCompleteCursorSaved, "checkInCompleteCursorSaved"}, + {Type::kDetachAttempt, "detachAttempt"}, + {Type::kDetachComplete, "detachComplete"}, + {Type::kNamespaceEntryMapErased, "namespaceEntryMapErased"}, + {Type::kRemoveCursorsSatisfyingPredicateAttempt, "killCursorsSatisfyingPredicateAttempt"}, + {Type::kRemoveCursorsSatisfyingPredicateComplete, "killCursorsSatisfyingPredicateComplete"}, + {Type::kKillCursorAttempt, "killCursorAttempt"}, + }; + + auto it = kMap.find(t); + if (it != kMap.end()) { + return it->second; + } + return "unknown " + std::to_string(static_cast<int>(t)); +} + +BSONObj ClusterCursorManager::dumpNssToContainerMap() const { + BSONObjBuilder bob; + // Record an object for the NSS -> Container map. + { + BSONObjBuilder nssToContainer(bob.subobjStart("nssToContainer")); + for (auto& nsContainerPair : _namespaceToContainerMap) { + BSONObjBuilder nssBob(nssToContainer.subobjStart(nsContainerPair.first.toString())); + nssBob.appendIntOrLL("containerPrefix", + static_cast<int64_t>(nsContainerPair.second.containerPrefix)); + BSONArrayBuilder cursors(nssBob.subarrayStart("cursors")); + for (auto& cursorIdEntryPair : nsContainerPair.second.entryMap) { + BSONObjBuilder cursorBob(cursors.subobjStart()); + cursorBob.appendIntOrLL("id", cursorIdEntryPair.first); + cursorBob.append("lastActive", cursorIdEntryPair.second.getLastActive()); + } + } + } + return bob.obj(); +} + +BSONObj ClusterCursorManager::dumpCursorIdToNssMap() const { + BSONObjBuilder bob; + + // Record an array for the Cursor ID Prefix -> NSS map. + { + BSONArrayBuilder cursorIdPrefixToNss(bob.subarrayStart("cursorIdPrefixToNss")); + for (auto& cursorIdPrefixNsPair : _cursorIdPrefixToNamespaceMap) { + BSONObjBuilder bob(cursorIdPrefixToNss.subobjStart()); + bob.appendIntOrLL("cursorIdPrefix", static_cast<int64_t>(cursorIdPrefixNsPair.first)); + bob.append("nss", cursorIdPrefixNsPair.second.toString()); + } + } + + return bob.obj(); +} + +BSONObj ClusterCursorManager::dumpInternalLog() const { + BSONObjBuilder bob; + // Dump the internal log maintained by the ClusterCursorManager. + { + BSONArrayBuilder logBuilder(bob.subarrayStart("log")); + size_t i = _log.start; + while (i != _log.end) { + BSONObjBuilder bob(logBuilder.subobjStart()); + const auto& logEntry = _log.events[i]; + if (logEntry.cursorId) { + bob.appendIntOrLL("cursorId", *logEntry.cursorId); + } + bob.append("type", LogEvent::typeToString(logEntry.type)); + + if (logEntry.time) { + bob.append("approxTime", *logEntry.time); + } + + if (logEntry.nss) { + bob.append("nss", logEntry.nss->toString()); + } + + i = (i + 1) % _log.events.size(); + } + } + return bob.obj(); +} } // namespace mongo diff --git a/src/mongo/s/query/cluster_cursor_manager.h b/src/mongo/s/query/cluster_cursor_manager.h index 57c139d941e..528139b15c4 100644 --- a/src/mongo/s/query/cluster_cursor_manager.h +++ b/src/mongo/s/query/cluster_cursor_manager.h @@ -455,6 +455,74 @@ private: using NssToCursorContainerMap = stdx::unordered_map<NamespaceString, CursorEntryContainer, NamespaceString::Hasher>; + // Internal, fixed size log of events cursor manager. This has been added to help diagnose + // SERVER-27796. + struct LogEvent { + enum class Type { + kRegisterAttempt, // Any attempt to create a cursor. + kRegisterComplete, // A cursor actually being created. + + // Checking out a cursor. + kCheckoutAttempt, + kCheckoutComplete, + + // Caller attempts to check a cursor in. This event may be followed by a + // kCheckInCompleteCursorSaved, or by events which indicate the cursor is deleted. + kCheckInAttempt, + + // Logged when the check-in is successful and the cursor is kept. + kCheckInCompleteCursorSaved, + + // Detaching a cursor (and erasing associated namespace). + kDetachAttempt, + kDetachComplete, + kNamespaceEntryMapErased, + + // These mark the beginning and end of the period where + // killCursorsSatisfyingPredicate() holds a lock. + kRemoveCursorsSatisfyingPredicateAttempt, + kRemoveCursorsSatisfyingPredicateComplete, + + // Any call to killCursor(). + kKillCursorAttempt, + + // Represents each time killCursorsSatisfyingPredicate() detaches a cursor that it + // intends to destroy. + kCursorMarkedForDeletionBySatisfyingPredicate, + + // + // NOTE: If you ever add to this enum be sure to update the typeToString() method + // below. + // + }; + + static std::string typeToString(Type); + + Type type; + + // boost::none for log entries that don't have an associated cursor ID. + boost::optional<CursorId> cursorId; + + // Time is not always provided to avoid having to read the clock while the mutex is held. + boost::optional<Date_t> time; + boost::optional<NamespaceString> nss; + }; + + // Circular queue used to store the latest events that happened in the ClusterCursorManager. + struct CircularLogQueue { + std::vector<LogEvent> events{512}; + size_t start = 0; + size_t end = 0; + + void push(LogEvent&& e) { + events[end] = std::move(e); + end = (end + 1) % events.size(); + if (end == start) { + start = (start + 1) % events.size(); + } + } + }; + /** * Transfers ownership of the given pinned cursor back to the manager, and moves the cursor to * the 'idle' state. @@ -506,13 +574,15 @@ private: void killOperationUsingCursor(WithLock, CursorEntry* entry); /** - * Kill the cursors satisfying the given predicate. Assumes that 'lk' is held upon entry. + * Kill the cursors satisfying the given predicate. Assumes that 'lk' is held upon entry. The + * 'now' parameter is only used for the internal logging mechansim. * * Returns the number of cursors killed. */ std::size_t killCursorsSatisfying(stdx::unique_lock<stdx::mutex> lk, OperationContext* opCtx, - std::function<bool(CursorId, const CursorEntry&)> pred); + std::function<bool(CursorId, const CursorEntry&)> pred, + Date_t now); /** * CursorEntry is a moveable, non-copyable container for a single cursor. @@ -646,6 +716,20 @@ private: */ NssToCursorContainerMap::iterator eraseContainer(NssToCursorContainerMap::iterator it); + /** + * Functions which dump the state/history of the cursor manager into a BSONObj for debug + * purposes. + */ + BSONObj dumpCursorIdToNssMap() const; + BSONObj dumpNssToContainerMap() const; + BSONObj dumpInternalLog() const; + + /** + * Logs objects which summarize the current state of the cursor manager as well as its recent + * history. + */ + void logCursorManagerInfo() const; + // Clock source. Used when the 'last active' time for a cursor needs to be set/updated. May be // concurrently accessed by multiple threads. ClockSource* _clockSource; @@ -656,6 +740,7 @@ private: bool _inShutdown{false}; // Randomness source. Used for cursor id generation. + const int64_t _randomSeed; PseudoRandom _pseudoRandom; // Map from cursor id prefix to associated namespace. Exists only to provide namespace lookup @@ -677,6 +762,8 @@ private: NssToCursorContainerMap _namespaceToContainerMap; size_t _cursorsTimedOut = 0; + + CircularLogQueue _log; }; } // namespace |