SERVER-13038 verbose query logging cleanup

19 files changed, 152 insertions, 103 deletions

diff --git a/src/mongo/db/matcher/expression_leaf.cpp b/src/mongo/db/matcher/expression_leaf.cpp
index 7e26569f4c8..68002636fbc 100644
--- a/src/mongo/db/matcher/expression_leaf.cpp
+++ b/src/mongo/db/matcher/expression_leaf.cpp
@@ -240,6 +240,10 @@ namespace mongo {
         debug << "\n";
     }
 
+    void RegexMatchExpression::shortDebugString( StringBuilder& debug ) const {
+        debug << "/" << _regex << "/" << _flags;
+    }
+
     // ---------
 
     Status ModMatchExpression::init( const StringData& path, int divisor, int remainder ) {
@@ -433,6 +437,18 @@ namespace mongo {
             toFillIn._regexes.push_back( static_cast<RegexMatchExpression*>(_regexes[i]->shallowClone()) );
     }
 
+    void ArrayFilterEntries::debugString( StringBuilder& debug ) const {
+        debug << "[ ";
+        for (BSONElementSet::const_iterator it = _equalities.begin();
+                it != _equalities.end(); ++it) {
+            debug << it->toString( false ) << " ";
+        }
+        for (size_t i = 0; i < _regexes.size(); ++i) {
+            _regexes[i]->shortDebugString( debug );
+            debug << " ";
+        }
+        debug << "]";
+    }
 
     // -----------
 
@@ -475,7 +491,8 @@ namespace mongo {
 
     void InMatchExpression::debugString( StringBuilder& debug, int level ) const {
         _debugAddSpace( debug, level );
-        debug << path() << ";$in: TODO ";
+        debug << path() << " $in ";
+        _arrayEntries.debugString(debug);
         MatchExpression::TagData* td = getTag();
         if (NULL != td) {
             debug << " ";
diff --git a/src/mongo/db/matcher/expression_leaf.h b/src/mongo/db/matcher/expression_leaf.h
index 29b346bb738..b7d88d06d14 100644
--- a/src/mongo/db/matcher/expression_leaf.h
+++ b/src/mongo/db/matcher/expression_leaf.h
@@ -204,6 +204,8 @@ namespace mongo {
 
         virtual void debugString( StringBuilder& debug, int level ) const;
 
+        void shortDebugString( StringBuilder& debug ) const;
+
         virtual bool equivalent( const MatchExpression* other ) const;
 
         const string& getString() const { return _regex; }
@@ -296,6 +298,8 @@ namespace mongo {
 
         void copyTo( ArrayFilterEntries& toFillIn ) const;
 
+        void debugString( StringBuilder& debug ) const;
+
     private:
         bool _hasNull; // if _equalities has a jstNULL element in it
         bool _hasEmptyArray;
diff --git a/src/mongo/db/matcher/expression_text.cpp b/src/mongo/db/matcher/expression_text.cpp
index 1a66a395946..f81c3dc1fa3 100644
--- a/src/mongo/db/matcher/expression_text.cpp
+++ b/src/mongo/db/matcher/expression_text.cpp
@@ -48,7 +48,7 @@ namespace mongo {
 
     void TextMatchExpression::debugString( StringBuilder& debug, int level ) const {
         _debugAddSpace(debug, level);
-        debug << "TEXT : query=" << _query << ", language = " << _language << ", tag=";
+        debug << "TEXT : query=" << _query << ", language=" << _language << ", tag=";
         MatchExpression::TagData* td = getTag();
         if ( NULL != td ) {
             td->debugString( &debug );
diff --git a/src/mongo/db/query/explain_plan.cpp b/src/mongo/db/query/explain_plan.cpp
index 0d571137aa3..d7c461261ba 100644
--- a/src/mongo/db/query/explain_plan.cpp
+++ b/src/mongo/db/query/explain_plan.cpp
@@ -28,8 +28,6 @@
 
 #include "mongo/db/query/explain_plan.h"
 
-#include <boost/algorithm/string/join.hpp>
-
 #include "mongo/db/exec/2dcommon.h"
 #include "mongo/db/query/stage_types.h"
 #include "mongo/db/query/type_explain.h"
@@ -606,14 +604,27 @@ namespace mongo {
 
     } // namespace
 
+    std::string getPlanSummary(const QuerySolution& soln) {
+        std::vector<std::string> leaves;
+        getLeafStrings(soln.root.get(), leaves);
+
+        mongoutils::str::stream ss;
+        for (size_t i = 0; i < leaves.size(); i++) {
+            ss << leaves[i];
+            if ((leaves.size() - 1) != i) {
+                ss << ", ";
+            }
+        }
+
+        return ss;
+    }
+
     void getPlanInfo(const QuerySolution& soln, PlanInfo** infoOut) {
         if (NULL == infoOut) { return; }
 
         *infoOut = new PlanInfo();
 
-        std::vector<std::string> leaves;
-        getLeafStrings(soln.root.get(), leaves);
-        (*infoOut)->planSummary = boost::algorithm::join(leaves, ", ");
+        (*infoOut)->planSummary = getPlanSummary(soln);
     }
 
 } // namespace mongo
diff --git a/src/mongo/db/query/explain_plan.h b/src/mongo/db/query/explain_plan.h
index e7e4314985c..7ffbd489914 100644
--- a/src/mongo/db/query/explain_plan.h
+++ b/src/mongo/db/query/explain_plan.h
@@ -68,6 +68,13 @@ namespace mongo {
                             TypeExplain** explain);
 
     /**
+     * Returns a short plan summary string describing the leaves of the query solution.
+     *
+     * Used for logging.
+     */
+    std::string getPlanSummary(const QuerySolution& soln);
+
+    /**
      * If the out-parameter 'info' is non-null, fills in '*infoOut' with information
      * from the query solution tree 'soln' that can be determined before the query is done
      * running. Whereas 'explainPlan(...)' above is for collecting runtime debug information,
diff --git a/src/mongo/db/query/get_runner.cpp b/src/mongo/db/query/get_runner.cpp
index 2e35743195c..cb394c48e73 100644
--- a/src/mongo/db/query/get_runner.cpp
+++ b/src/mongo/db/query/get_runner.cpp
@@ -35,6 +35,7 @@
 #include "mongo/db/query/cached_plan_runner.h"
 #include "mongo/db/query/canonical_query.h"
 #include "mongo/db/query/eof_runner.h"
+#include "mongo/db/query/explain_plan.h"
 #include "mongo/db/query/query_settings.h"
 #include "mongo/db/query/idhack_runner.h"
 #include "mongo/db/query/index_bounds_builder.h"
@@ -296,6 +297,8 @@ namespace mongo {
                     }
                 }
 
+                LOG(2) << "Using cached query plan: " << getPlanSummary(*qs);
+
                 WorkingSet* ws;
                 PlanStage* root;
                 verify(StageBuilder::build(*qs, &root, &ws));
diff --git a/src/mongo/db/query/index_bounds_builder.cpp b/src/mongo/db/query/index_bounds_builder.cpp
index 59df9828b53..dde33031d08 100644
--- a/src/mongo/db/query/index_bounds_builder.cpp
+++ b/src/mongo/db/query/index_bounds_builder.cpp
@@ -717,7 +717,6 @@ namespace mongo {
 
         const string start = simpleRegex(rme->getString().c_str(), rme->getFlags().c_str(), tightnessOut);
 
-        // QLOG() << "regex bounds start is " << start << endl;
         // Note that 'tightnessOut' is set by simpleRegex above.
         if (!start.empty()) {
             string end = start;
@@ -831,7 +830,6 @@ namespace mongo {
                 std::reverse(iv.begin(), iv.end());
                 // Step 2: reverse each interval.
                 for (size_t i = 0; i < iv.size(); ++i) {
-                    QLOG() << "reversing " << iv[i].toString() << endl;
                     iv[i].reverse();
                 }
             }
@@ -839,9 +837,9 @@ namespace mongo {
         }
 
         if (!bounds->isValidFor(kp, scanDir)) {
-            QLOG() << "INVALID BOUNDS: " << bounds->toString() << endl;
-            QLOG() << "kp = " << kp.toString() << endl;
-            QLOG() << "scanDir = " << scanDir << endl;
+            QLOG() << "INVALID BOUNDS: " << bounds->toString() << endl
+                   << "kp = " << kp.toString() << endl
+                   << "scanDir = " << scanDir << endl;
             verify(0);
         }
     }
diff --git a/src/mongo/db/query/index_tag.h b/src/mongo/db/query/index_tag.h
index 55df1f4e65a..060bf7212cc 100644
--- a/src/mongo/db/query/index_tag.h
+++ b/src/mongo/db/query/index_tag.h
@@ -95,7 +95,7 @@ namespace mongo {
         std::string pathPrefix;
 
         virtual void debugString(StringBuilder* builder) const {
-            *builder << "First: ";
+            *builder << " || First: ";
             for (size_t i = 0; i < first.size(); ++i) {
                 *builder << first[i] << " ";
             }
diff --git a/src/mongo/db/query/multi_plan_runner.cpp b/src/mongo/db/query/multi_plan_runner.cpp
index 276f84b5b1c..77d056bf3e9 100644
--- a/src/mongo/db/query/multi_plan_runner.cpp
+++ b/src/mongo/db/query/multi_plan_runner.cpp
@@ -275,7 +275,7 @@ namespace mongo {
         RunnerState state = _bestPlan->getNext(objOut, dlOut);
 
         if (Runner::RUNNER_ERROR == state && (NULL != _backupSolution)) {
-            QLOG() << "Best plan errored out switching to backup\n";
+            QLOG() << "Best plan errored out; switching to backup.\n";
             // Uncache the bad solution if we fall back
             // on the backup solution.
             //
@@ -299,7 +299,7 @@ namespace mongo {
         }
 
         if (NULL != _backupSolution && Runner::RUNNER_ADVANCED == state) {
-            QLOG() << "Best plan had a blocking sort, became unblocked, deleting backup plan\n";
+            QLOG() << "Best plan had a blocking sort, became unblocked; deleting backup plan.\n";
             delete _backupSolution;
             delete _backupPlan;
             _backupSolution = NULL;
@@ -339,13 +339,14 @@ namespace mongo {
         _bestSolution.reset(_candidates[bestChild].solution);
 
         QLOG() << "Winning solution:\n" << _bestSolution->toString() << endl;
+        LOG(2) << "Winning plan: " << getPlanSummary(*_bestSolution);
 
         size_t backupChild = bestChild;
         if (_bestSolution->hasBlockingStage && (0 == _alreadyProduced.size())) {
-            QLOG() << "Winner has blocking stage, looking for backup plan...\n";
+            QLOG() << "Winner has blocking stage, looking for backup plan.\n";
             for (size_t i = 0; i < _candidates.size(); ++i) {
                 if (!_candidates[i].solution->hasBlockingStage) {
-                    QLOG() << "Candidate " << i << " is backup child\n";
+                    QLOG() << "Candidate " << i << " is backup child.\n";
                     backupChild = i;
                     _backupSolution = _candidates[i].solution;
                     _backupAlreadyProduced = _candidates[i].results;
diff --git a/src/mongo/db/query/new_find.cpp b/src/mongo/db/query/new_find.cpp
index ee580697593..3d8365591bb 100644
--- a/src/mongo/db/query/new_find.cpp
+++ b/src/mongo/db/query/new_find.cpp
@@ -136,7 +136,7 @@ namespace mongo {
         Collection* collection = ctx->ctx().db()->getCollection(ns);
         uassert( 17356, "collection dropped between getMore calls", collection );
 
-        QLOG() << "running getMore in new system, cursorid " << cursorid << endl;
+        QLOG() << "Running getMore, cursorid: " << cursorid << endl;
 
         // This checks to make sure the operation is allowed on a replicated node.  Since we are not
         // passing in a query object (necessary to check SlaveOK query option), the only state where
@@ -275,7 +275,7 @@ namespace mongo {
                 // cc is now invalid, as is the runner
                 cursorid = 0;
                 cc = NULL;
-                QLOG() << "getMore NOT saving client cursor, ended w/state "
+                QLOG() << "getMore NOT saving client cursor, ended with state "
                        << Runner::statestr(state)
                        << endl;
             }
@@ -283,7 +283,7 @@ namespace mongo {
                 // Continue caching the ClientCursor.
                 cc->incPos(numResults);
                 runner->saveState();
-                QLOG() << "getMore saving client cursor ended w/state "
+                QLOG() << "getMore saving client cursor ended with state "
                        << Runner::statestr(state)
                        << endl;
 
@@ -416,7 +416,10 @@ namespace mongo {
         }
         verify(cq);
 
-        QLOG() << "Running query on new system: " << cq->toString();
+        QLOG() << "Running query:\n" << cq->toString();
+        LOG(2) << "Running query: query " << cq->getParsed().getFilter().toString()
+               << " sort " << cq->getParsed().getSort().toString()
+               << " projection " << cq->getParsed().getProj().toString();
 
         // Parse, canonicalize, plan, transcribe, and get a runner.
         Runner* rawRunner = NULL;
@@ -720,7 +723,7 @@ namespace mongo {
             cc->setLeftoverMaxTimeMicros(curop.getRemainingMaxTimeMicros());
         }
         else {
-            QLOG() << "not caching runner but returning " << numResults << " results\n";
+            QLOG() << "Not caching runner but returning " << numResults << " results.\n";
         }
 
         // Add the results from the query into the output buffer.
diff --git a/src/mongo/db/query/plan_enumerator.cpp b/src/mongo/db/query/plan_enumerator.cpp
index f8228da9603..3317c516296 100644
--- a/src/mongo/db/query/plan_enumerator.cpp
+++ b/src/mongo/db/query/plan_enumerator.cpp
@@ -64,8 +64,6 @@ namespace mongo {
     }
 
     Status PlanEnumerator::init() {
-        QLOG() << "enumerator received root:\n" << _root->toString() << endl;
-
         // Fill out our memo structure from the tagged _root.
         _done = !prepMemo(_root, PrepMemoContext());
 
@@ -75,43 +73,47 @@ namespace mongo {
         return Status::OK();
     }
 
-    void PlanEnumerator::dumpMemo() {
+    std::string PlanEnumerator::dumpMemo() {
+        mongoutils::str::stream ss;
         for (size_t i = 0; i < _memo.size(); ++i) {
-            QLOG() << "[Node #" << i << "]: " << _memo[i]->toString() << endl;
+            ss << "[Node #" << i << "]: " << _memo[i]->toString() << "\n";
         }
+        return ss;
     }
 
     string PlanEnumerator::NodeAssignment::toString() const {
         if (NULL != pred) {
             mongoutils::str::stream ss;
-            ss << "predicate, first indices: [";
+            ss << "predicate\n";
+            ss << "\tfirst indices: [";
             for (size_t i = 0; i < pred->first.size(); ++i) {
                 ss << pred->first[i];
                 if (i < pred->first.size() - 1)
                     ss << ", ";
             }
-            ss << "], pred: " << pred->expr->toString();
-            ss << " indexToAssign: " << pred->indexToAssign;
+            ss << "]\n";
+            ss << "\tpred: " << pred->expr->toString();
+            ss << "\tindexToAssign: " << pred->indexToAssign;
             return ss;
         }
         else if (NULL != andAssignment) {
             mongoutils::str::stream ss;
             ss << "AND enumstate counter " << andAssignment->counter;
             for (size_t i = 0; i < andAssignment->choices.size(); ++i) {
-                ss << "\nchoice " << i << ":\n";
+                ss << "\n\tchoice " << i << ":\n";
                 const AndEnumerableState& state = andAssignment->choices[i];
-                ss << "\tsubnodes: ";
+                ss << "\t\tsubnodes: ";
                 for (size_t j = 0; j < state.subnodesToIndex.size(); ++j) {
                     ss << state.subnodesToIndex[j] << " ";
                 }
                 ss << '\n';
                 for (size_t j = 0; j < state.assignments.size(); ++j) {
                     const OneIndexAssignment& oie = state.assignments[j];
-                    ss << "\tidx[" << oie.index << "]\n";
+                    ss << "\t\tidx[" << oie.index << "]\n";
 
                     for (size_t k = 0; k < oie.preds.size(); ++k) {
-                        ss << "\t\tpos " << oie.positions[k]
-                           << " pred " << oie.preds[k]->toString() << '\n';
+                        ss << "\t\t\tpos " << oie.positions[k]
+                           << " pred " << oie.preds[k]->toString();
                     }
                 }
             }
@@ -119,9 +121,9 @@ namespace mongo {
         }
         else if (NULL != arrayAssignment) {
             mongoutils::str::stream ss;
-            ss << "ARRAY SUBNODES enumstate " << arrayAssignment->counter << "/ ONE OF: [";
+            ss << "ARRAY SUBNODES enumstate " << arrayAssignment->counter << "/ ONE OF: [ ";
             for (size_t i = 0; i < arrayAssignment->subnodes.size(); ++i) {
-                ss << " " << arrayAssignment->subnodes[i];
+                ss << arrayAssignment->subnodes[i] << " ";
             }
             ss << "]";
             return ss;
@@ -129,9 +131,9 @@ namespace mongo {
         else {
             verify(NULL != orAssignment);
             mongoutils::str::stream ss;
-            ss << "ALL OF: [";
+            ss << "ALL OF: [ ";
             for (size_t i = 0; i < orAssignment->subnodes.size(); ++i) {
-                ss << " " << orAssignment->subnodes[i];
+                ss << orAssignment->subnodes[i] << " ";
             }
             ss << "]";
             return ss;
@@ -149,11 +151,8 @@ namespace mongo {
         sortUsingTags(*tree);
 
         _root->resetTag();
-        QLOG() << "Enumerator: memo right before moving:\n";
-        dumpMemo();
+        QLOG() << "Enumerator: memo just before moving:" << endl << dumpMemo();
         _done = nextMemo(_nodeToId[_root]);
-        QLOG() << "Enumerator: memo right after moving:\n";
-        dumpMemo();
         return true;
     }
 
diff --git a/src/mongo/db/query/plan_enumerator.h b/src/mongo/db/query/plan_enumerator.h
index 139c9351693..9cd850e2ab0 100644
--- a/src/mongo/db/query/plan_enumerator.h
+++ b/src/mongo/db/query/plan_enumerator.h
@@ -360,7 +360,7 @@ namespace mongo {
                       const IndexEntry& thisIndex,
                       OneIndexAssignment* assign);
 
-        void dumpMemo();
+        std::string dumpMemo();
 
         // Map from expression to its MemoID.
         unordered_map<MatchExpression*, MemoID> _nodeToId;
diff --git a/src/mongo/db/query/plan_ranker.cpp b/src/mongo/db/query/plan_ranker.cpp
index af110dcdefc..fc2d3b9d4b3 100644
--- a/src/mongo/db/query/plan_ranker.cpp
+++ b/src/mongo/db/query/plan_ranker.cpp
@@ -89,13 +89,16 @@ namespace mongo {
 
         // Compute score for each tree.  Record the best.
         for (size_t i = 0; i < statTrees.size(); ++i) {
-            QLOG() << "scoring plan " << i << ":"
-                   << candidates[i].solution->toString() << "\n stats:\n"
+            QLOG() << "Scoring plan " << i << ":" << endl
+                   << candidates[i].solution->toString() << "Stats:\n"
                    << statsToBSON(*statTrees[i]).jsonString(Strict, true);
+            LOG(2) << "Scoring query plan: " << getPlanSummary(*candidates[i].solution)
+                   << " planHitEOF=" << statTrees[i]->common.isEOF;
+
             double score = scoreTree(statTrees[i]);
             QLOG() << "score = " << score << endl;
             if (statTrees[i]->common.isEOF) {
-                QLOG() << "adding +" << eofBonus << " EOF bonus to score" << endl;
+                QLOG() << "Adding +" << eofBonus << " EOF bonus to score." << endl;
                 score += 1;
             }
             scoresAndCandidateindices.push_back(std::make_pair(score, i));
@@ -225,29 +228,32 @@ namespace mongo {
         double tieBreakers = noFetchBonus + noSortBonus + noIxisectBonus;
         double score = baseScore + productivity + tieBreakers;
 
-        QLOG() << "score (" << score << ") = baseScore(" << baseScore << ")"
-                                     <<  " + productivity((" << stats->common.advanced
-                                                             << " advanced)/("
-                                                             << stats->common.works
-                                                             << " works + "
-                                                             << stats->common.needFetch
-                                                             << " needFetch) = "
-                                                             << productivity << ")"
-                                     <<  " + tieBreakers(" << noFetchBonus
-                                                           << " noFetchBonus + "
-                                                           << noSortBonus
-                                                           << " noSortBonus + "
-                                                           << noIxisectBonus
-                                                           << " noIxisectBonus = "
-                                                           << tieBreakers << ")"
-                                     << endl;
+        mongoutils::str::stream ss;
+        ss << "score(" << score << ") = baseScore(" << baseScore << ")"
+                                <<  " + productivity((" << stats->common.advanced
+                                                        << " advanced)/("
+                                                        << stats->common.works
+                                                        << " works + "
+                                                        << stats->common.needFetch
+                                                        << " needFetch) = "
+                                                        << productivity << ")"
+                                <<  " + tieBreakers(" << noFetchBonus
+                                                      << " noFetchBonus + "
+                                                      << noSortBonus
+                                                      << " noSortBonus + "
+                                                      << noIxisectBonus
+                                                      << " noIxisectBonus = "
+                                                      << tieBreakers << ")";
+        std::string scoreStr = ss;
+        QLOG() << scoreStr << endl;
+        LOG(2) << scoreStr;
 
         if (forceIntersectionPlans) {
             if (hasStage(STAGE_AND_HASH, stats) || hasStage(STAGE_AND_SORTED, stats)) {
                 // The boost should be >2.001 to make absolutely sure the ixisect plan will win due
                 // to the combination of 1) productivity, 2) eof bonus, and 3) no ixisect bonus.
                 score += 3;
-                QLOG() << "score boosted to " << score << " due to forceIntersectionPlans" << endl;
+                QLOG() << "Score boosted to " << score << " due to forceIntersectionPlans." << endl;
             }
         }
 
diff --git a/src/mongo/db/query/planner_access.cpp b/src/mongo/db/query/planner_access.cpp
index 0e6c385e8bf..ec95896f0ce 100644
--- a/src/mongo/db/query/planner_access.cpp
+++ b/src/mongo/db/query/planner_access.cpp
@@ -86,7 +86,6 @@ namespace mongo {
             }
         }
 
-        // QLOG() << "Outputting collscan " << soln->toString() << endl;
         return csn;
     }
 
@@ -96,7 +95,6 @@ namespace mongo {
                                                         size_t pos,
                                                         MatchExpression* expr,
                                                         IndexBoundsBuilder::BoundsTightness* tightnessOut) {
-        // QLOG() << "making leaf node for " << expr->toString() << endl;
         // We're guaranteed that all GEO_NEARs are first.  This slightly violates the "sort index
         // predicates by their position in the compound index" rule but GEO_NEAR isn't an ixscan.
         // This saves our bacon when we have {foo: 1, bar: "2dsphere"} and the predicate on bar is a
@@ -148,8 +146,6 @@ namespace mongo {
             return ret;
         }
         else {
-            // QLOG() << "making ixscan for " << expr->toString() << endl;
-
             // Note that indexKeyPattern.firstElement().fieldName() may not equal expr->path()
             // because expr might be inside an array operator that provides a path prefix.
             IndexScanNode* isn = new IndexScanNode();
@@ -172,7 +168,6 @@ namespace mongo {
             IndexBoundsBuilder::translate(expr, keyElt, index, &isn->bounds.fields[pos],
                                           tightnessOut);
 
-            // QLOG() << "bounds are " << isn->bounds.toString() << " exact " << *exact << endl;
             return isn;
         }
     }
diff --git a/src/mongo/db/query/planner_analysis.cpp b/src/mongo/db/query/planner_analysis.cpp
index 9dfa6b331df..44372f11333 100644
--- a/src/mongo/db/query/planner_analysis.cpp
+++ b/src/mongo/db/query/planner_analysis.cpp
@@ -367,7 +367,7 @@ namespace mongo {
         BSONObj reverseSort = QueryPlannerCommon::reverseSortObj(sortObj);
         if (sorts.end() != sorts.find(reverseSort)) {
             QueryPlannerCommon::reverseScans(solnRoot);
-            QLOG() << "Reversing ixscan to provide sort.  Result: "
+            QLOG() << "Reversing ixscan to provide sort. Result: "
                    << solnRoot->toString() << endl;
             return solnRoot;
         }
@@ -524,7 +524,7 @@ namespace mongo {
                 bool covered = true;
                 for (size_t i = 0; i < fields.size(); ++i) {
                     if (!solnRoot->hasField(fields[i])) {
-                        QLOG() << "PROJECTION: not covered cuz doesn't have field "
+                        QLOG() << "PROJECTION: not covered due to field "
                              << fields[i] << endl;
                         covered = false;
                         break;
diff --git a/src/mongo/db/query/qlog.h b/src/mongo/db/query/qlog.h
index 8fce6f12ced..a7d83f7d52b 100644
--- a/src/mongo/db/query/qlog.h
+++ b/src/mongo/db/query/qlog.h
@@ -35,7 +35,7 @@ namespace mongo {
     extern bool verboseQueryLogging;
 
 // With a #define like this, we don't evaluate the costly toString()s that are QLOG'd
-#define QLOG() if (verboseQueryLogging) log()
+#define QLOG() if (verboseQueryLogging) log() << "[QLOG] "
 
     bool qlogOff();
     bool qlogOn();
diff --git a/src/mongo/db/query/query_planner.cpp b/src/mongo/db/query/query_planner.cpp
index 0fb752a6175..68c8efa674f 100644
--- a/src/mongo/db/query/query_planner.cpp
+++ b/src/mongo/db/query/query_planner.cpp
@@ -86,8 +86,15 @@ namespace mongo {
             ss << "INCLUDE_SHARD_FILTER ";
         }
         if (options & QueryPlannerParams::NO_BLOCKING_SORT) {
-            ss << "NO_BLOCKING_SORT";
+            ss << "NO_BLOCKING_SORT ";
         }
+        if (options & QueryPlannerParams::INDEX_INTERSECTION) {
+            ss << "INDEX_INTERSECTION ";
+        }
+        if (options & QueryPlannerParams::KEEP_MUTATIONS) {
+            ss << "KEEP_MUTATIONS";
+        }
+
         return ss;
     }
 
@@ -326,7 +333,7 @@ namespace mongo {
             // Takes ownership of 'solnRoot'.
             QuerySolution* soln = QueryPlannerAnalysis::analyzeDataAccess(query, params, solnRoot);
             if (NULL != soln) {
-                QLOG() << "Planner: adding cached solution:\n" << soln->toString() << endl;
+                QLOG() << "Planner: solution constructed from the cache:\n" << soln->toString() << endl;
                 *out = soln;
                 return Status::OK();
             }
@@ -376,14 +383,14 @@ namespace mongo {
                               const QueryPlannerParams& params,
                               std::vector<QuerySolution*>* out) {
 
-        QLOG() << "=============================\n"
-               << "Beginning planning, options = " << optionString(params.options) << endl
-               << "Canonical query:\n" << query.toString() << endl
-               << "============================="
-               << endl;
+        QLOG() << "Beginning planning..." << endl
+               << "=============================" << endl
+               << "Options = " << optionString(params.options) << endl
+               << "Canonical query:" << endl << query.toString()
+               << "=============================" << endl;
 
         for (size_t i = 0; i < params.indices.size(); ++i) {
-            QLOG() << "idx " << i << " is " << params.indices[i].toString() << endl;
+            QLOG() << "Index " << i << " is " << params.indices[i].toString() << endl;
         }
 
         bool canTableScan = !(params.options & QueryPlannerParams::NO_TABLE_SCAN);
@@ -408,7 +415,7 @@ namespace mongo {
         if (!query.getParsed().getHint().isEmpty()) {
             BSONElement natural = query.getParsed().getHint().getFieldDotted("$natural");
             if (!natural.eoo()) {
-                QLOG() << "forcing a table scan due to hinted $natural\n";
+                QLOG() << "Forcing a table scan due to hinted $natural\n";
                 // min/max are incompatible with $natural.
                 if (canTableScan && query.getParsed().getMin().isEmpty()
                                  && query.getParsed().getMax().isEmpty()) {
@@ -426,7 +433,7 @@ namespace mongo {
         QueryPlannerIXSelect::getFields(query.root(), "", &fields);
 
         for (unordered_set<string>::const_iterator it = fields.begin(); it != fields.end(); ++it) {
-            QLOG() << "predicate over field " << *it << endl;
+            QLOG() << "Predicate over field '" << *it << "'" << endl;
         }
 
         // Filter our indices so we only look at indices that are over our predicates.
@@ -465,8 +472,8 @@ namespace mongo {
                 string hintName = firstHintElt.String();
                 for (size_t i = 0; i < params.indices.size(); ++i) {
                     if (params.indices[i].name == hintName) {
-                        QLOG() << "hint by name specified, restricting indices to "
-                             << params.indices[i].keyPattern.toString() << endl;
+                        QLOG() << "Hint by name specified, restricting indices to "
+                               << params.indices[i].keyPattern.toString() << endl;
                         relevantIndices.clear();
                         relevantIndices.push_back(params.indices[i]);
                         hintIndexNumber = i;
@@ -480,8 +487,8 @@ namespace mongo {
                     if (0 == params.indices[i].keyPattern.woCompare(hintIndex)) {
                         relevantIndices.clear();
                         relevantIndices.push_back(params.indices[i]);
-                        QLOG() << "hint specified, restricting indices to " << hintIndex.toString()
-                             << endl;
+                        QLOG() << "Hint specified, restricting indices to " << hintIndex.toString()
+                               << endl;
                         hintIndexNumber = i;
                         break;
                     }
@@ -505,13 +512,13 @@ namespace mongo {
             // If there's an index hinted we need to be able to use it.
             if (!hintIndex.isEmpty()) {
                 if (!minObj.isEmpty() && !indexCompatibleMaxMin(minObj, hintIndex)) {
-                    QLOG() << "minobj doesnt work w hint";
+                    QLOG() << "Minobj doesn't work with hint";
                     return Status(ErrorCodes::BadValue,
                                   "hint provided does not work with min query");
                 }
 
                 if (!maxObj.isEmpty() && !indexCompatibleMaxMin(maxObj, hintIndex)) {
-                    QLOG() << "maxobj doesnt work w hint";
+                    QLOG() << "Maxobj doesn't work with hint";
                     return Status(ErrorCodes::BadValue,
                                   "hint provided does not work with max query");
                 }
@@ -531,7 +538,7 @@ namespace mongo {
                     }
                 }
             }
-            
+
             if (idxNo == numeric_limits<size_t>::max()) {
                 QLOG() << "Can't find relevant index to use for max/min query";
                 // Can't find an index to use, bail out.
@@ -556,7 +563,7 @@ namespace mongo {
                 maxObj = stripFieldNames(maxObj);
             }
 
-            QLOG() << "max/min query using index " << params.indices[idxNo].toString() << endl;
+            QLOG() << "Max/min query using index " << params.indices[idxNo].toString() << endl;
 
             // Make our scan and output.
             QuerySolutionNode* solnRoot = QueryPlannerAccess::makeIndexScan(params.indices[idxNo],
@@ -574,7 +581,8 @@ namespace mongo {
         }
 
         for (size_t i = 0; i < relevantIndices.size(); ++i) {
-            QLOG() << "relevant idx " << i << " is " << relevantIndices[i].toString() << endl;
+            QLOG() << "Relevant index " << i << " is " << relevantIndices[i].toString() << endl;
+            LOG(2) << "Relevant index " << i << " is " << relevantIndices[i].toString() << endl;
         }
 
         // Figure out how useful each index is to each predicate.
@@ -582,8 +590,7 @@ namespace mongo {
         QueryPlannerIXSelect::stripInvalidAssignments(query.root(), relevantIndices);
 
         // query.root() is now annotated with RelevantTag(s).
-        QLOG() << "rated tree" << endl;
-        QLOG() << query.root()->toString() << endl;
+        QLOG() << "Rated tree:" << endl << query.root()->toString();
 
         // If there is a GEO_NEAR it must have an index it can use directly.
         MatchExpression* gnNode = NULL;
@@ -591,7 +598,7 @@ namespace mongo {
             // No index for GEO_NEAR?  No query.
             RelevantTag* tag = static_cast<RelevantTag*>(gnNode->getTag());
             if (0 == tag->first.size() && 0 == tag->notFirst.size()) {
-                QLOG() << "unable to find index for $geoNear query" << endl;
+                QLOG() << "Unable to find index for $geoNear query." << endl;
                 return Status(ErrorCodes::BadValue, "unable to find index for $geoNear query");
             }
 
@@ -689,8 +696,8 @@ namespace mongo {
 
             MatchExpression* rawTree;
             while (isp.getNext(&rawTree) && (out->size() < params.maxIndexedSolutions)) {
-                QLOG() << "about to build solntree from tagged tree:\n" << rawTree->toString()
-                       << endl;
+                QLOG() << "About to build solntree from tagged tree:" << endl
+                       << rawTree->toString();
 
                 // The tagged tree produced by the plan enumerator is not guaranteed
                 // to be canonically sorted. In order to be compatible with the cached
@@ -713,7 +720,7 @@ namespace mongo {
 
                 QuerySolution* soln = QueryPlannerAnalysis::analyzeDataAccess(query, params, solnRoot);
                 if (NULL != soln) {
-                    QLOG() << "Planner: adding solution:\n" << soln->toString() << endl;
+                    QLOG() << "Planner: adding solution:" << endl << soln->toString();
                     if (indexTreeStatus.isOK()) {
                         SolutionCacheData* scd = new SolutionCacheData();
                         scd->tree.reset(autoData.release());
@@ -838,8 +845,8 @@ namespace mongo {
                 scd->solnType = SolutionCacheData::COLLSCAN_SOLN;
                 collscan->cacheData.reset(scd);
                 out->push_back(collscan);
-                QLOG() << "Planner: outputting a collscan:\n";
-                QLOG() << collscan->toString() << endl;
+                QLOG() << "Planner: outputting a collscan:" << endl
+                       << collscan->toString();
             }
         }
 
diff --git a/src/mongo/db/query/query_planner_common.h b/src/mongo/db/query/query_planner_common.h
index ba529b05606..1b66f96ec0b 100644
--- a/src/mongo/db/query/query_planner_common.h
+++ b/src/mongo/db/query/query_planner_common.h
@@ -104,7 +104,7 @@ namespace mongo {
                 }
 
                 if (!isn->bounds.isValidFor(isn->indexKeyPattern, isn->direction)) {
-                    QLOG() << "invalid bounds: " << isn->bounds.toString() << endl;
+                    QLOG() << "Invalid bounds: " << isn->bounds.toString() << endl;
                     verify(0);
                 }
 
diff --git a/src/mongo/db/query/query_solution.cpp b/src/mongo/db/query/query_solution.cpp
index f98802aa732..55b132482d6 100644
--- a/src/mongo/db/query/query_solution.cpp
+++ b/src/mongo/db/query/query_solution.cpp
@@ -92,7 +92,7 @@ namespace mongo {
         *ss <<  "ns = " << name << '\n';
         if (NULL != filter) {
             addIndent(ss, indent + 1);
-            *ss << " filter = " << filter->toString();
+            *ss << "filter = " << filter->toString();
         }
         addCommon(ss, indent);
     }
@@ -323,14 +323,12 @@ namespace mongo {
         *ss << "keyPattern = " << indexKeyPattern << '\n';
         if (NULL != filter) {
             addIndent(ss, indent + 1);
-            *ss << " filter= " << filter->toString() << '\n';
+            *ss << "filter = " << filter->toString();
         }
         addIndent(ss, indent + 1);
         *ss << "direction = " << direction << '\n';
         addIndent(ss, indent + 1);
         *ss << "bounds = " << bounds.toString() << '\n';
-        addIndent(ss, indent + 1);
-        *ss << "fetched = " << fetched() << '\n';
         addCommon(ss, indent);
     }