summaryrefslogtreecommitdiff
path: root/src/mongo
diff options
context:
space:
mode:
authorNeil Shweky <neilshweky@gmail.com>2021-10-21 15:32:04 +0000
committerEvergreen Agent <no-reply@evergreen.mongodb.com>2021-10-21 16:23:28 +0000
commite45de6eba5a9efde4d8074d478db48499e9333c8 (patch)
tree9998b975d4321dc57dea2f75602ee5fdc3f91aa4 /src/mongo
parent79cbc3d7168a4bebf185381bf57ac4769ddb3f42 (diff)
downloadmongo-e45de6eba5a9efde4d8074d478db48499e9333c8.tar.gz
SERVER-59936: Remove logging from ClusterCursorManager
Diffstat (limited to 'src/mongo')
-rw-r--r--src/mongo/s/query/cluster_cursor_manager.cpp137
-rw-r--r--src/mongo/s/query/cluster_cursor_manager.h84
2 files changed, 0 insertions, 221 deletions
diff --git a/src/mongo/s/query/cluster_cursor_manager.cpp b/src/mongo/s/query/cluster_cursor_manager.cpp
index 72422330bfe..4087d33d74f 100644
--- a/src/mongo/s/query/cluster_cursor_manager.cpp
+++ b/src/mongo/s/query/cluster_cursor_manager.cpp
@@ -180,7 +180,6 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor(
const auto now = _clockSource->now();
stdx::unique_lock<Latch> lk(_mutex);
- _log.push({LogEvent::Type::kRegisterAttempt, boost::none, now, nss});
if (_inShutdown) {
lk.unlock();
@@ -238,7 +237,6 @@ StatusWith<CursorId> ClusterCursorManager::registerCursor(
opCtx->getClient()->getUUID(),
opCtx->getOperationKey()));
invariant(emplaceResult.second);
- _log.push({LogEvent::Type::kRegisterComplete, cursorId, now, nss});
return cursorId;
}
@@ -249,10 +247,8 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur
OperationContext* opCtx,
AuthzCheckFn authChecker,
AuthCheck checkSessionAuth) {
- const auto now = _clockSource->now();
stdx::lock_guard<Latch> lk(_mutex);
- _log.push({LogEvent::Type::kCheckoutAttempt, cursorId, now, nss});
if (_inShutdown) {
return Status(ErrorCodes::ShutdownInProgress,
@@ -298,7 +294,6 @@ StatusWith<ClusterCursorManager::PinnedCursor> ClusterCursorManager::checkOutCur
CurOp::get(opCtx)->debug().queryHash = cursorGuard->getQueryHash();
- _log.push({LogEvent::Type::kCheckoutComplete, cursorId, now, nss});
return PinnedCursor(this, std::move(cursorGuard), nss, cursorId);
}
@@ -317,7 +312,6 @@ void ClusterCursorManager::checkInCursor(std::unique_ptr<ClusterClientCursor> cu
cursor->setLastUseDate(now);
stdx::unique_lock<Latch> lk(_mutex);
- _log.push({LogEvent::Type::kCheckInAttempt, cursorId, now, nss});
CursorEntry* entry = _getEntry(lk, nss, cursorId);
invariant(entry);
@@ -329,7 +323,6 @@ 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;
}
@@ -371,11 +364,8 @@ Status ClusterCursorManager::killCursor(OperationContext* opCtx,
CursorId cursorId) {
invariant(opCtx);
- const auto now = _clockSource->now();
stdx::unique_lock<Latch> lk(_mutex);
- _log.push({LogEvent::Type::kKillCursorAttempt, cursorId, now, nss});
-
CursorEntry* entry = _getEntry(lk, nss, cursorId);
if (!entry) {
return cursorNotFoundStatus(nss, cursorId);
@@ -440,13 +430,9 @@ void ClusterCursorManager::killAllCursors(OperationContext* opCtx) {
std::size_t ClusterCursorManager::killCursorsSatisfying(
OperationContext* opCtx, const std::function<bool(CursorId, const CursorEntry&)>& pred) {
invariant(opCtx);
- const auto now = _clockSource->now();
stdx::unique_lock<Latch> lk(_mutex);
std::size_t nKilled = 0;
- _log.push(
- {LogEvent::Type::kRemoveCursorsSatisfyingPredicateAttempt, boost::none, now, boost::none});
-
std::vector<ClusterClientCursorGuard> cursorsToDestroy;
auto nsContainerIt = _namespaceToContainerMap.begin();
while (nsContainerIt != _namespaceToContainerMap.end()) {
@@ -470,14 +456,6 @@ 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(opCtx));
// Destroy the entry and set the iterator to the next element.
@@ -491,14 +469,6 @@ 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});
-
// Ensure cursors are killed outside the lock, as killing may require waiting for callbacks to
// finish.
lk.unlock();
@@ -730,15 +700,10 @@ auto ClusterCursorManager::eraseContainer(NssToCursorContainerMap::iterator it)
"nss"_attr = it->first,
"prefix"_attr = container.containerPrefix,
"actualNumDeleted"_attr = 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;
@@ -748,7 +713,6 @@ StatusWith<ClusterClientCursorGuard> ClusterCursorManager::_detachCursor(WithLoc
OperationContext* opCtx,
const NamespaceString& nss,
CursorId cursorId) {
- _log.push({LogEvent::Type::kDetachAttempt, cursorId, boost::none, nss});
CursorEntry* entry = _getEntry(lk, nss, cursorId);
if (!entry) {
return cursorNotFoundStatus(nss, cursorId);
@@ -771,107 +735,6 @@ StatusWith<ClusterClientCursorGuard> ClusterCursorManager::_detachCursor(WithLoc
eraseContainer(nsToContainerIt);
}
- _log.push({LogEvent::Type::kDetachComplete, cursorId, boost::none, nss});
-
return std::move(cursor);
}
-
-void ClusterCursorManager::logCursorManagerInfo() const {
- LOGV2_ERROR_OPTIONS(4786900,
- logv2::LogTruncation::Disabled,
- "Dumping cursor manager contents. "
- "NSS -> Container map: {nssToContainer} "
- "Cursor ID Prefix -> NSS map: {cursorIdToNss} "
- "Internal log: {internalLog}",
- "Dumping cursor manager contents.",
- "{nssToContainer}"_attr = dumpNssToContainerMap(),
- "{cursorIdToNss}"_attr = dumpCursorIdToNssMap(),
- "{internalLog}"_attr = dumpInternalLog());
-}
-
-std::string ClusterCursorManager::LogEvent::typeToString(ClusterCursorManager::LogEvent::Type t) {
- const static stdx::unordered_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"},
- };
-
- if (auto it = kMap.find(t); 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&& [nss, cursorContainer] : _namespaceToContainerMap) {
- BSONObjBuilder nssBob(nssToContainer.subobjStart(nss.toString()));
- nssBob.appendNumber("containerPrefix",
- static_cast<long long>(cursorContainer.containerPrefix));
- BSONArrayBuilder cursors(nssBob.subarrayStart("cursors"));
- for (auto&& [cursorId, cursorEntry] : cursorContainer.entryMap) {
- BSONObjBuilder cursorBob(cursors.subobjStart());
- cursorBob.appendNumber("id", cursorId);
- cursorBob.append("lastActive", cursorEntry.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&& [cursorIdPrefix, nss] : _cursorIdPrefixToNamespaceMap) {
- BSONObjBuilder bob(cursorIdPrefixToNss.subobjStart());
- bob.appendNumber("cursorIdPrefix", static_cast<long long>(cursorIdPrefix));
- bob.append("nss", nss.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.appendNumber("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 a10db367159..7df393e3403 100644
--- a/src/mongo/s/query/cluster_cursor_manager.h
+++ b/src/mongo/s/query/cluster_cursor_manager.h
@@ -541,74 +541,6 @@ private:
using CursorEntryMap = stdx::unordered_map<CursorId, CursorEntry>;
using NssToCursorContainerMap = stdx::unordered_map<NamespaceString, CursorEntryContainer>;
- // 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.
@@ -686,20 +618,6 @@ 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;
@@ -732,8 +650,6 @@ private:
NssToCursorContainerMap _namespaceToContainerMap;
size_t _cursorsTimedOut = 0;
-
- CircularLogQueue _log;
};
} // namespace mongo