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");
}
