TEST(LockStats, Wait) {
const ResourceId resId(RESOURCE_COLLECTION, std::string("LockStats.Wait"));
resetGlobalLockStats();
LockerForTests locker(MODE_IX);
locker.lock(resId, MODE_X);
{
// This will block
LockerForTests lockerConflict(MODE_IX);
ASSERT_EQUALS(LOCK_WAITING, lockerConflict.lockBegin(resId, MODE_S));
// Sleep 1 millisecond so the wait time passes
ASSERT_EQUALS(LOCK_TIMEOUT, lockerConflict.lockComplete(resId, MODE_S, 1, false));
}
// Make sure that the waits/blocks are non-zero
SingleThreadedLockStats stats;
reportGlobalLockingStats(&stats);
ASSERT_EQUALS(1, stats.get(resId, MODE_X).numAcquisitions);
ASSERT_EQUALS(0, stats.get(resId, MODE_X).numWaits);
ASSERT_EQUALS(0, stats.get(resId, MODE_X).combinedWaitTimeMicros);
ASSERT_EQUALS(1, stats.get(resId, MODE_S).numAcquisitions);
ASSERT_EQUALS(1, stats.get(resId, MODE_S).numWaits);
ASSERT_GREATER_THAN(stats.get(resId, MODE_S).combinedWaitTimeMicros, 0);
}
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" , ns.toString() );
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 );
b.append( "millis" , executionTime );
execStats.append(b, "execStats");
}
TEST(LockStats, Reporting) {
const ResourceId resId(RESOURCE_COLLECTION, std::string("LockStats.Reporting"));
resetGlobalLockStats();
LockerForTests locker(MODE_IX);
locker.lock(resId, MODE_X);
locker.unlock(resId);
// Make sure that the waits/blocks are zero
SingleThreadedLockStats stats;
reportGlobalLockingStats(&stats);
BSONObjBuilder builder;
stats.report(&builder);
}
TEST(LockStats, NoWait) {
const ResourceId resId(RESOURCE_COLLECTION, std::string("LockStats.NoWait"));
resetGlobalLockStats();
LockerForTests locker(MODE_IX);
locker.lock(resId, MODE_X);
locker.unlock(resId);
// Make sure that the waits/blocks are zero
SingleThreadedLockStats stats;
reportGlobalLockingStats(&stats);
ASSERT_EQUALS(1, stats.get(resId, MODE_X).numAcquisitions);
ASSERT_EQUALS(0, stats.get(resId, MODE_X).numWaits);
ASSERT_EQUALS(0, stats.get(resId, MODE_X).combinedWaitTimeMicros);
}
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();
}
string OpDebug::report(const CurOp& curop, const SingleThreadedLockStats& lockStats) const {
StringBuilder s;
if ( iscommand )
s << "command ";
else
s << opToString( op ) << ' ';
s << ns.toString();
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->name << " ";
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 (!planSummary.empty()) {
s << " planSummary: " << planSummary.toString();
}
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( nscanned );
OPDEBUG_TOSTRING_HELP( nscannedObjects );
OPDEBUG_TOSTRING_HELP_BOOL( idhack );
OPDEBUG_TOSTRING_HELP_BOOL( scanAndOrder );
OPDEBUG_TOSTRING_HELP( nmoved );
OPDEBUG_TOSTRING_HELP( nMatched );
OPDEBUG_TOSTRING_HELP( nModified );
OPDEBUG_TOSTRING_HELP( ninserted );
OPDEBUG_TOSTRING_HELP( ndeleted );
OPDEBUG_TOSTRING_HELP_BOOL( fastmod );
OPDEBUG_TOSTRING_HELP_BOOL( fastmodinsert );
OPDEBUG_TOSTRING_HELP_BOOL( upsert );
OPDEBUG_TOSTRING_HELP_BOOL( cursorExhausted );
OPDEBUG_TOSTRING_HELP( keyUpdates );
OPDEBUG_TOSTRING_HELP( writeConflicts );
if ( extra.len() )
s << " " << extra.str();
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();
}
s << " " << executionTime << "ms";
return s.str();
}