void profile(OperationContext* txn, const Client& c, int op, CurOp& currentOp) { // initialize with 1kb to start, to avoid realloc later // doing this outside the dblock to improve performance BufBuilder profileBufBuilder(1024); try { // NOTE: It's kind of weird that we lock the op's namespace, but have to for now since // we're sometimes inside the lock already Lock::DBWrite lk(txn->lockState(), currentOp.getNS() ); if (dbHolder().get(txn, nsToDatabase(currentOp.getNS())) != NULL) { // We are ok with the profiling happening in a different WUOW from the actual op. WriteUnitOfWork wunit(txn->recoveryUnit()); Client::Context cx(txn, currentOp.getNS(), false); _profile(txn, c, cx.db(), currentOp, profileBufBuilder); wunit.commit(); } else { mongo::log() << "note: not profiling because db went away - probably a close on: " << currentOp.getNS() << endl; } } catch (const AssertionException& assertionEx) { warning() << "Caught Assertion while trying to profile " << opToString(op) << " against " << currentOp.getNS() << ": " << assertionEx.toString() << endl; } }
void profile(OperationContext* txn, const Client& c, int op, CurOp& currentOp) { // initialize with 1kb to start, to avoid realloc later // doing this outside the dblock to improve performance BufBuilder profileBufBuilder(1024); try { // NOTE: It's kind of weird that we lock the op's namespace, but have to for now since // we're sometimes inside the lock already Lock::DBWrite lk( currentOp.getNS() ); if (dbHolder()._isLoaded(nsToDatabase(currentOp.getNS()), storageGlobalParams.dbpath)) { Client::Context cx(currentOp.getNS(), storageGlobalParams.dbpath, false); _profile(txn, c, cx.db(), currentOp, profileBufBuilder); } else { mongo::log() << "note: not profiling because db went away - probably a close on: " << currentOp.getNS() << endl; } } catch (const AssertionException& assertionEx) { warning() << "Caught Assertion while trying to profile " << opToString(op) << " against " << currentOp.getNS() << ": " << assertionEx.toString() << endl; } }
void profile( const Client& c , CurOp& currentOp, int millis) { assertInWriteLock(); string info = currentOp.debug().str.str(); profileBufBuilder.reset(); BSONObjBuilder b(profileBufBuilder); b.appendDate("ts", jsTime()); b.append("info", info); b.append("millis", (double) millis); if ( currentOp.getNS() ) b.append( "ns" , currentOp.getNS() ); b.append("client", c.clientAddress() ); BSONObj p = b.done(); // write: not replicated Database *db = c.database(); const char *ns = db->profileName.c_str(); NamespaceDetails *d = db->namespaceIndex.details(ns); if( d ) { int len = p.objsize(); Record *r = theDataFileMgr.fast_oplog_insert(d, ns, len); memcpy(getDur().writingPtr(r->data, len), p.objdata(), len); } else { static time_t last; if( time(0) > last+10 ) { log() << "profile: warning ns " << ns << " does not exist" << endl; last = time(0); } } }
// Profile the current op in an alternate transaction void lockedDoProfile(const Client& c, int op, CurOp& currentOp) { if ( dbHolder().__isLoaded( nsToDatabase( currentOp.getNS() ) , dbpath ) ) { Client::Context ctx(currentOp.getNS(), dbpath); Client::AlternateTransactionStack altStack; Client::Transaction txn(DB_SERIALIZABLE); profile(c, op, currentOp); txn.commit(); } }
void profile(OperationContext* txn, const Client& c, int op, CurOp& currentOp) { // initialize with 1kb to start, to avoid realloc later // doing this outside the dblock to improve performance BufBuilder profileBufBuilder(1024); bool tryAgain = false; while ( 1 ) { try { // NOTE: It's kind of weird that we lock the op's namespace, but have to for now // since we're sometimes inside the lock already const string dbname(nsToDatabase(currentOp.getNS())); scoped_ptr<Lock::DBLock> lk; // todo: this can be slow, perhaps can re-work if ( !txn->lockState()->isDbLockedForMode( dbname, MODE_IX ) ) { lk.reset( new Lock::DBLock( txn->lockState(), dbname, tryAgain ? MODE_X : MODE_IX) ); } Database* db = dbHolder().get(txn, dbname); if (db != NULL) { // We want the profiling to happen in a different WUOW from the actual op. Lock::CollectionLock clk(txn->lockState(), db->getProfilingNS(), MODE_X); WriteUnitOfWork wunit(txn); Client::Context cx(txn, currentOp.getNS(), false); if ( !_profile(txn, c, cx.db(), currentOp, profileBufBuilder ) && lk.get() ) { if ( tryAgain ) { // we couldn't profile, but that's ok, we should have logged already break; } // we took an IX lock, so now we try again with an X lock tryAgain = true; continue; } wunit.commit(); } else { mongo::log() << "note: not profiling because db went away - " << "probably a close on: " << currentOp.getNS(); } return; } catch (const AssertionException& assertionEx) { warning() << "Caught Assertion while trying to profile " << opToString(op) << " against " << currentOp.getNS() << ": " << assertionEx.toString() << endl; return; } } }
void profile(const Client& c, int op, CurOp& currentOp) { // initialize with 1kb to start, to avoid realloc later // doing this outside the dblock to improve performance BufBuilder profileBufBuilder(1024); try { Lock::DBWrite lk( currentOp.getNS() ); if ( dbHolder()._isLoaded( nsToDatabase( currentOp.getNS() ) , dbpath ) ) { Client::Context cx(currentOp.getNS(), dbpath); _profile(c, currentOp, profileBufBuilder); } else { mongo::log() << "note: not profiling because db went away - probably a close on: " << currentOp.getNS() << endl; } } catch (const AssertionException& assertionEx) { warning() << "Caught Assertion while trying to profile " << opToString(op) << " against " << currentOp.getNS() << ": " << assertionEx.toString() << endl; } }
void OpDebug::append(const CurOp& curop, const SingleThreadedLockStats& lockStats, BSONObjBuilder& b) const { const size_t maxElementSize = 50 * 1024; b.append("op", logicalOpToString(logicalOp)); NamespaceString nss = NamespaceString(curop.getNS()); b.append("ns", nss.ns()); if (!iscommand && networkOp == dbQuery) { appendAsObjOrString( "query", upconvertQueryEntry(query, nss, ntoreturn, ntoskip), maxElementSize, &b); } else if (!iscommand && networkOp == dbGetMore) { appendAsObjOrString( "query", upconvertGetMoreEntry(nss, cursorid, ntoreturn), maxElementSize, &b); } else if (!query.isEmpty()) { const char* fieldName = (logicalOp == LogicalOp::opCommand) ? "command" : "query"; appendAsObjOrString(fieldName, query, maxElementSize, &b); } else if (!iscommand && curop.haveQuery()) { appendAsObjOrString("query", curop.query(), maxElementSize, &b); } if (!updateobj.isEmpty()) { appendAsObjOrString("updateobj", updateobj, maxElementSize, &b); } OPDEBUG_APPEND_NUMBER(cursorid); OPDEBUG_APPEND_BOOL(exhaust); OPDEBUG_APPEND_NUMBER(keysExamined); OPDEBUG_APPEND_NUMBER(docsExamined); OPDEBUG_APPEND_BOOL(hasSortStage); OPDEBUG_APPEND_BOOL(fromMultiPlanner); OPDEBUG_APPEND_BOOL(replanned); OPDEBUG_APPEND_NUMBER(nMatched); OPDEBUG_APPEND_NUMBER(nModified); OPDEBUG_APPEND_NUMBER(ninserted); OPDEBUG_APPEND_NUMBER(ndeleted); OPDEBUG_APPEND_BOOL(fastmodinsert); OPDEBUG_APPEND_BOOL(upsert); OPDEBUG_APPEND_BOOL(cursorExhausted); if (nmoved > 0) { b.appendNumber("nmoved", nmoved); } if (keysInserted > 0) { b.appendNumber("keysInserted", keysInserted); } if (keysDeleted > 0) { b.appendNumber("keysDeleted", keysDeleted); } if (writeConflicts > 0) { b.appendNumber("writeConflicts", writeConflicts); } b.appendNumber("numYield", curop.numYields()); { BSONObjBuilder locks(b.subobjStart("locks")); lockStats.report(&locks); } if (!exceptionInfo.empty()) { exceptionInfo.append(b, "exception", "exceptionCode"); } OPDEBUG_APPEND_NUMBER(nreturned); OPDEBUG_APPEND_NUMBER(responseLength); if (iscommand) { b.append("protocol", getProtoString(networkOp)); } b.append("millis", executionTime); if (!curop.getPlanSummary().empty()) { b.append("planSummary", curop.getPlanSummary()); } if (execStats.have()) { execStats.append(b, "execStats"); } }
string OpDebug::report(const CurOp& curop, const SingleThreadedLockStats& lockStats) const { StringBuilder s; if (iscommand) s << "command "; else s << networkOpToString(networkOp) << ' '; s << curop.getNS(); if (!query.isEmpty()) { if (iscommand) { s << " command: "; Command* curCommand = curop.getCommand(); if (curCommand) { mutablebson::Document cmdToLog(query, mutablebson::Document::kInPlaceDisabled); curCommand->redactForLogging(&cmdToLog); s << curCommand->getName() << " "; s << cmdToLog.toString(); } else { // Should not happen but we need to handle curCommand == NULL gracefully s << query.toString(); } } else { s << " query: "; s << query.toString(); } } if (!curop.getPlanSummary().empty()) { s << " planSummary: " << curop.getPlanSummary(); } if (!updateobj.isEmpty()) { s << " update: "; updateobj.toString(s); } OPDEBUG_TOSTRING_HELP(cursorid); OPDEBUG_TOSTRING_HELP(ntoreturn); OPDEBUG_TOSTRING_HELP(ntoskip); OPDEBUG_TOSTRING_HELP_BOOL(exhaust); OPDEBUG_TOSTRING_HELP(keysExamined); OPDEBUG_TOSTRING_HELP(docsExamined); OPDEBUG_TOSTRING_HELP_BOOL(hasSortStage); OPDEBUG_TOSTRING_HELP_BOOL(fromMultiPlanner); OPDEBUG_TOSTRING_HELP_BOOL(replanned); OPDEBUG_TOSTRING_HELP(nMatched); OPDEBUG_TOSTRING_HELP(nModified); OPDEBUG_TOSTRING_HELP(ninserted); OPDEBUG_TOSTRING_HELP(ndeleted); OPDEBUG_TOSTRING_HELP_BOOL(fastmodinsert); OPDEBUG_TOSTRING_HELP_BOOL(upsert); OPDEBUG_TOSTRING_HELP_BOOL(cursorExhausted); if (nmoved > 0) { s << " nmoved:" << nmoved; } if (keysInserted > 0) { s << " keysInserted:" << keysInserted; } if (keysDeleted > 0) { s << " keysDeleted:" << keysDeleted; } if (writeConflicts > 0) { s << " writeConflicts:" << writeConflicts; } if (!exceptionInfo.empty()) { s << " exception: " << exceptionInfo.msg; if (exceptionInfo.code) s << " code:" << exceptionInfo.code; } s << " numYields:" << curop.numYields(); OPDEBUG_TOSTRING_HELP(nreturned); if (responseLength > 0) { s << " reslen:" << responseLength; } { BSONObjBuilder locks; lockStats.report(&locks); s << " locks:" << locks.obj().toString(); } if (iscommand) { s << " protocol:" << getProtoString(networkOp); } s << " " << executionTime << "ms"; return s.str(); }
void OpDebug::append(const CurOp& curop, const SingleThreadedLockStats& lockStats, BSONObjBuilder& b) const { const size_t maxElementSize = 50 * 1024; b.append("op", iscommand ? "command" : opToString(op)); b.append("ns", curop.getNS()); if (!query.isEmpty()) { appendAsObjOrString(iscommand ? "command" : "query", query, maxElementSize, &b); } else if (!iscommand && curop.haveQuery()) { appendAsObjOrString("query", curop.query(), maxElementSize, &b); } if (!updateobj.isEmpty()) { appendAsObjOrString("updateobj", updateobj, maxElementSize, &b); } const bool moved = (nmoved >= 1); OPDEBUG_APPEND_NUMBER(cursorid); OPDEBUG_APPEND_NUMBER(ntoreturn); OPDEBUG_APPEND_NUMBER(ntoskip); OPDEBUG_APPEND_BOOL(exhaust); OPDEBUG_APPEND_NUMBER(nscanned); OPDEBUG_APPEND_NUMBER(nscannedObjects); OPDEBUG_APPEND_BOOL(idhack); OPDEBUG_APPEND_BOOL(scanAndOrder); OPDEBUG_APPEND_BOOL(moved); OPDEBUG_APPEND_NUMBER(nmoved); OPDEBUG_APPEND_NUMBER(nMatched); OPDEBUG_APPEND_NUMBER(nModified); OPDEBUG_APPEND_NUMBER(ninserted); OPDEBUG_APPEND_NUMBER(ndeleted); OPDEBUG_APPEND_BOOL(fastmod); OPDEBUG_APPEND_BOOL(fastmodinsert); OPDEBUG_APPEND_BOOL(upsert); OPDEBUG_APPEND_BOOL(cursorExhausted); OPDEBUG_APPEND_NUMBER(keyUpdates); OPDEBUG_APPEND_NUMBER(writeConflicts); b.appendNumber("numYield", curop.numYields()); { BSONObjBuilder locks(b.subobjStart("locks")); lockStats.report(&locks); } if (!exceptionInfo.empty()) { exceptionInfo.append(b, "exception", "exceptionCode"); } OPDEBUG_APPEND_NUMBER(nreturned); OPDEBUG_APPEND_NUMBER(responseLength); if (iscommand) { b.append("protocol", getProtoString(op)); } b.append("millis", executionTime); execStats.append(b, "execStats"); }