Permalink
Browse files

SERVER-12774 added nscanned and nscannedObjects to slow query log

  • Loading branch information...
1 parent bad0ae5 commit 7766137467a41c02d053d81b65d55349bd865b29 @benety benety committed Feb 24, 2014
View
@@ -30,12 +30,18 @@ if(db.isMaster().msg != "isdbgrid") {
// ensure that slow query is logged in detail
assert( contains(resp.log, function(v) {
print(v);
- return v.indexOf(" query ") != -1 && v.indexOf("query:") != -1 && v.indexOf("SENTINEL") != -1;
+ return v.indexOf(" query ") != -1 && v.indexOf("query:") != -1 &&
+ v.indexOf("nscanned:") != -1 &&
+ v.indexOf("nscannedObjects:") != -1 &&
+ v.indexOf("SENTINEL") != -1;
}) );
// same, but for update
assert( contains(resp.log, function(v) {
print(v);
- return v.indexOf(" update ") != -1 && v.indexOf("query:") != -1 && v.indexOf("SENTINEL") != -1;
+ return v.indexOf(" update ") != -1 && v.indexOf("query:") != -1 &&
+ v.indexOf("nscanned:") != -1 &&
+ v.indexOf("nscannedObjects:") != -1 &&
+ v.indexOf("SENTINEL") != -1;
}) );
}
View
@@ -553,6 +553,7 @@ namespace mongo {
exhaust = false;
nscanned = -1;
+ nscannedObjects = -1;
idhack = false;
scanAndOrder = false;
nMatched = -1;
@@ -620,6 +621,7 @@ namespace mongo {
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 );
@@ -712,6 +714,7 @@ namespace mongo {
OPDEBUG_APPEND_BOOL( exhaust );
OPDEBUG_APPEND_NUMBER( nscanned );
+ OPDEBUG_APPEND_NUMBER( nscannedObjects );
OPDEBUG_APPEND_BOOL( idhack );
OPDEBUG_APPEND_BOOL( scanAndOrder );
OPDEBUG_APPEND_BOOL( moved );
View
@@ -341,12 +341,15 @@ namespace mongo {
static Counter64 updatedCounter;
static Counter64 deletedCounter;
static Counter64 scannedCounter;
+ static Counter64 scannedObjectCounter;
static ServerStatusMetricField<Counter64> displayReturned( "document.returned", &returnedCounter );
static ServerStatusMetricField<Counter64> displayUpdated( "document.updated", &updatedCounter );
static ServerStatusMetricField<Counter64> displayInserted( "document.inserted", &insertedCounter );
static ServerStatusMetricField<Counter64> displayDeleted( "document.deleted", &deletedCounter );
static ServerStatusMetricField<Counter64> displayScanned( "queryExecutor.scanned", &scannedCounter );
+ static ServerStatusMetricField<Counter64> displayScannedObjects( "queryExecutor.scannedObjects",
+ &scannedObjectCounter );
static Counter64 idhackCounter;
static Counter64 scanAndOrderCounter;
@@ -367,6 +370,8 @@ namespace mongo {
deletedCounter.increment( ndeleted );
if ( nscanned > 0 )
scannedCounter.increment( nscanned );
+ if ( nscannedObjects > 0 )
+ scannedObjectCounter.increment( nscannedObjects );
if ( idhack )
idhackCounter.increment();
View
@@ -155,6 +155,7 @@ namespace mongo {
// debugging/profile info
long long nscanned;
+ long long nscannedObjects;
bool idhack; // indicates short circuited code path on an update to make the update faster
bool scanAndOrder; // scanandorder query plan aspect was used
long long nMatched; // number of records that match the query
@@ -539,6 +539,7 @@ namespace mongo {
// reflecting only the actions taken locally. In particlar, we must have the no-op
// counter reset so that we can meaningfully comapre it with numMatched above.
opDebug->nscanned = 0;
+ opDebug->nscannedObjects = 0;
opDebug->nModified = 0;
// Get the cached document from the update driver.
@@ -610,6 +611,7 @@ namespace mongo {
opDebug->nscanned++;
// Found a matching document
+ opDebug->nscannedObjects++;
numMatched++;
// Ask the driver to apply the mods. It may be that the driver can apply those "in
@@ -613,10 +613,19 @@ namespace mongo {
shardingState.getVersion(pq.ns()));
}
- // Get explain information if it is needed by either the profiler
- // or by an explain() query.
+ // Used to fill in explain and to determine if the query is slow enough to be logged.
+ int elapsedMillis = curop.elapsedMillis();
+
+ // Get explain information if:
+ // 1) it is needed by an explain query;
+ // 2) profiling is enabled; or
+ // 3) profiling is disabled but we still need explain details to log a "slow" query.
+ // Producing explain information is expensive and should be done only if we are certain
+ // the information will be used.
boost::scoped_ptr<TypeExplain> explain(NULL);
- if (isExplain || ctx.ctx().db()->getProfilingLevel() > 0) {
+ if (isExplain ||
+ ctx.ctx().db()->getProfilingLevel() > 0 ||
+ elapsedMillis > serverGlobalParams.slowMS) {
// Ask the runner to produce explain information.
TypeExplain* bareExplain;
Status res = runner->getInfo(&bareExplain, NULL);
@@ -648,7 +657,7 @@ namespace mongo {
explain->setN(numResults);
// Clock the whole operation.
- explain->setMillis(curop.elapsedMillis());
+ explain->setMillis(elapsedMillis);
BSONObj explainObj = explain->toBSON();
bb.appendBuf((void*)explainObj.objdata(), explainObj.objsize());
@@ -725,6 +734,10 @@ namespace mongo {
curop.debug().nscanned = explain->getNScanned();
}
+ if (explain->isNScannedObjectsSet()) {
+ curop.debug().nscannedObjects = explain->getNScannedObjects();
+ }
+
if (explain->isIDHackSet()) {
curop.debug().idhack = explain->getIDHack();
}

0 comments on commit 7766137

Please sign in to comment.