SERVER-6218 Profiler should only abbreviate query/updateobj

5 files changed, 115 insertions, 225 deletions

diff --git a/jstests/core/profile2.js b/jstests/core/profile2.js
index 1006c03a40d..50ffde1d84f 100644
--- a/jstests/core/profile2.js
+++ b/jstests/core/profile2.js
@@ -1,25 +1,77 @@
-print("profile2.js BEGIN");
+// Tests that large queries and updates are properly profiled.
 
-// special db so that it can be run in parallel tests
-var stddb = db;
-var db = db.getSisterDB("profile2");
+// Special db so that it can be run in parallel tests.
+var coll = db.getSisterDB("profile2").profile2;
 
-try {
+assert.commandWorked(coll.getDB().runCommand({profile: 0}));
+coll.drop();
+coll.getDB().system.profile.drop();
+assert.commandWorked(coll.getDB().runCommand({profile: 2}));
 
-    assert.commandWorked( db.runCommand( {profile:2} ) );
+var str = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";
+var hugeStr = str;
+while (hugeStr.length < 2*1024*1024){
+    hugeStr += str;
+}
+
+// Test query with large string element.
+coll.find({a: hugeStr}).itcount();
+var results = coll.getDB().system.profile.find().toArray();
+assert.eq(1, results.length);
+var result = results[0];
+assert(result.hasOwnProperty('ns'));
+assert(result.hasOwnProperty('millis'));
+assert(result.hasOwnProperty('query'));
+assert.eq('string', typeof(result.query));
+assert(result.query.match(/^{ a: "a+\.\.\." }$/)); // String value is truncated.
+
+assert.commandWorked(coll.getDB().runCommand({profile: 0}));
+coll.getDB().system.profile.drop();
+assert.commandWorked(coll.getDB().runCommand({profile: 2}));
 
-    var str = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";
-    huge = str;
-    while (huge.length < 2*1024*1024){
-        huge += str;
-    }
+// Test update with large string element in query portion.
+assert.writeOK(coll.update({a: hugeStr}, {}));
+var results = coll.getDB().system.profile.find().toArray();
+assert.eq(1, results.length);
+var result = results[0];
+assert(result.hasOwnProperty('ns'));
+assert(result.hasOwnProperty('millis'));
+assert(result.hasOwnProperty('query'));
+assert.eq('string', typeof(result.query));
+assert(result.query.match(/^{ a: "a+\.\.\." }$/)); // String value is truncated.
 
-    db.profile2.count({huge:huge}) // would make a huge entry in db.system.profile
+assert.commandWorked(coll.getDB().runCommand({profile: 0}));
+coll.getDB().system.profile.drop();
+assert.commandWorked(coll.getDB().runCommand({profile: 2}));
 
-    print("profile2.js SUCCESS OK");
-    
-} finally {
-    // disable profiling for subsequent tests
-    assert.commandWorked( db.runCommand( {profile:0} ) );
-    db = stddb;
+// Test update with large string element in update portion.
+assert.writeOK(coll.update({}, {a: hugeStr}));
+var results = coll.getDB().system.profile.find().toArray();
+assert.eq(1, results.length);
+var result = results[0];
+assert(result.hasOwnProperty('ns'));
+assert(result.hasOwnProperty('millis'));
+assert(result.hasOwnProperty('updateobj'));
+assert.eq('string', typeof(result.updateobj));
+assert(result.updateobj.match(/^{ a: "a+\.\.\." }$/)); // String value is truncated.
+
+assert.commandWorked(coll.getDB().runCommand({profile: 0}));
+coll.getDB().system.profile.drop();
+assert.commandWorked(coll.getDB().runCommand({profile: 2}));
+
+// Test query with many elements in query portion.
+var doc = {};
+for (var i = 0; i < 100 * 1000; ++i) {
+    doc["a" + i] = 1;
 }
+coll.find(doc).itcount();
+var results = coll.getDB().system.profile.find().toArray();
+assert.eq(1, results.length);
+var result = results[0];
+assert(result.hasOwnProperty('ns'));
+assert(result.hasOwnProperty('millis'));
+assert(result.hasOwnProperty('query'));
+assert.eq('string', typeof(result.query));
+assert(result.query.match(/^{ a0: 1\.0, a1: .*\.\.\.$/)); // Query object itself is truncated.
+
+assert.commandWorked(coll.getDB().runCommand({profile: 0}));
diff --git a/src/mongo/db/client.cpp b/src/mongo/db/client.cpp
index 947d545f8d6..21e25cd2266 100644
--- a/src/mongo/db/client.cpp
+++ b/src/mongo/db/client.cpp
@@ -495,54 +495,58 @@ namespace mongo {
         return s.str();
     }
 
-#define OPDEBUG_APPEND_NUMBER(x) if( x != -1 ) b.appendNumber( #x , (x) )
-#define OPDEBUG_APPEND_BOOL(x) if( x ) b.appendBool( #x , (x) )
-    bool OpDebug::append(const CurOp& curop, BSONObjBuilder& b, size_t maxSize) const {
-        b.append( "op" , iscommand ? "command" : opToString( op ) );
-        b.append( "ns" , ns.toString() );
-        
-        int queryUpdateObjSize = 0;
-        if (!query.isEmpty()) {
-            queryUpdateObjSize += query.objsize();
-        }
-        else if (!iscommand && curop.haveQuery()) {
-            queryUpdateObjSize += curop.query()["query"].size();
-        }
-
-        if (!updateobj.isEmpty()) {
-            queryUpdateObjSize += updateobj.objsize();
-        }
-
-        if (static_cast<size_t>(queryUpdateObjSize) > maxSize) {
-            if (!query.isEmpty()) {
-                // Use 60 since BSONObj::toString can truncate strings into 150 chars
-                // and we want to have enough room for both query and updateobj when
-                // the entire document is going to be serialized into a string
-                const string abbreviated(query.toString(false, false), 0, 60);
-                b.append(iscommand ? "command" : "query", abbreviated + "...");
+    namespace {
+        /**
+         * Appends {name: obj} to the provided builder.  If obj is greater than maxSize, appends a
+         * string summary of obj instead of the object itself.
+         */
+        void appendAsObjOrString(const StringData& name,
+                                 const BSONObj& obj,
+                                 size_t maxSize,
+                                 BSONObjBuilder* builder) {
+            if (static_cast<size_t>(obj.objsize()) <= maxSize) {
+                builder->append(name, obj);
             }
-            else if (!iscommand && curop.haveQuery()) {
-                const string abbreviated(curop.query()["query"].toString(false, false), 0, 60);
-                b.append("query", abbreviated + "...");
+            else {
+                // Generate an abbreviated serialization for the object, by passing false as the
+                // "full" argument to obj.toString().
+                const bool isArray = false;
+                const bool full = false;
+                std::string objToString = obj.toString(isArray, full);
+                if (objToString.size() <= maxSize) {
+                    builder->append(name, objToString);
+                }
+                else {
+                    // objToString is still too long, so we append to the builder a truncated form
+                    // of objToString concatenated with "...".  Instead of creating a new string
+                    // temporary, mutate objToString to do this (we know that we can mutate
+                    // characters in objToString up to and including objToString[maxSize]).
+                    objToString[maxSize - 3] = '.';
+                    objToString[maxSize - 2] = '.';
+                    objToString[maxSize - 1] = '.';
+                    builder->append(name, StringData(objToString).substr(0, maxSize));
+                }
             }
+        }
+    }
 
-            if (!updateobj.isEmpty()) {
-                const string abbreviated(updateobj.toString(false, false), 0, 60);
-                b.append("updateobj", abbreviated + "...");
-            }
+#define OPDEBUG_APPEND_NUMBER(x) if( x != -1 ) b.appendNumber( #x , (x) )
+#define OPDEBUG_APPEND_BOOL(x) if( x ) b.appendBool( #x , (x) )
+    void OpDebug::append(const CurOp& curop, BSONObjBuilder& b) const {
+        const size_t maxElementSize = 50 * 1024;
 
-            return false;
-        }
+        b.append( "op" , iscommand ? "command" : opToString( op ) );
+        b.append( "ns" , ns.toString() );
 
         if (!query.isEmpty()) {
-            b.append(iscommand ? "command" : "query", query);
+            appendAsObjOrString(iscommand ? "command" : "query", query, maxElementSize, &b);
         }
         else if (!iscommand && curop.haveQuery()) {
-            curop.appendQuery(b, "query");
+            appendAsObjOrString("query", curop.query(), maxElementSize, &b);
         }
 
         if (!updateobj.isEmpty()) {
-            b.append("updateobj", updateobj);
+            appendAsObjOrString("updateobj", updateobj, maxElementSize, &b);
         }
 
         const bool moved = (nmoved >= 1);
@@ -578,8 +582,6 @@ namespace mongo {
         b.append( "millis" , executionTime );
 
         execStats.append(b, "execStats");
-
-        return true;
     }
 
     void saveGLEStats(const BSONObj& result, const std::string& conn) {
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 4e42f85cc93..7b781e7051a 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -129,19 +129,10 @@ namespace mongo {
         std::string report( const CurOp& curop ) const;
 
         /**
-         * Appends stored data and information from curop to the builder.
-         *
-         * @param curop information about the current operation which will be
-         *     use to append data to the builder.
-         * @param builder the BSON builder to use for appending data. Data can
-         *     still be appended even if this method returns false.
-         * @param maxSize the maximum allowed combined size for the query object
-         *     and update object
-         *
-         * @return false if the sum of the sizes for the query object and update
-         *     object exceeded maxSize
+         * Appends information about the current operation to "builder".  "curop" must be a
+         * reference to the CurOp that owns this OpDebug.
          */
-        bool append(const CurOp& curop, BSONObjBuilder& builder, size_t maxSize) const;
+        void append(const CurOp& curop, BSONObjBuilder& builder) const;
 
         // -------------------
         
diff --git a/src/mongo/db/introspect.cpp b/src/mongo/db/introspect.cpp
index 9218ad25774..6dd6c323a99 100644
--- a/src/mongo/db/introspect.cpp
+++ b/src/mongo/db/introspect.cpp
@@ -45,10 +45,6 @@
 #include "mongo/util/goodies.h"
 #include "mongo/util/log.h"
 
-namespace {
-    const size_t MAX_PROFILE_DOC_SIZE_BYTES = 100*1024;
-}
-
 namespace mongo {
 
 namespace {
@@ -94,8 +90,7 @@ namespace {
         // build object
         BSONObjBuilder b(profileBufBuilder);
 
-        const bool isQueryObjTooBig = !currentOp.debug().append(currentOp, b,
-                MAX_PROFILE_DOC_SIZE_BYTES);
+        currentOp.debug().append(currentOp, b);
 
         b.appendDate("ts", jsTime());
         b.append("client", c.clientAddress());
@@ -105,27 +100,6 @@ namespace {
 
         BSONObj p = b.done();
 
-        if (static_cast<size_t>(p.objsize()) > MAX_PROFILE_DOC_SIZE_BYTES || isQueryObjTooBig) {
-            string small = p.toString(/*isArray*/false, /*full*/false);
-
-            warning() << "can't add full line to system.profile: " << small << endl;
-
-            // rebuild with limited info
-            BSONObjBuilder b(profileBufBuilder);
-            b.appendDate("ts", jsTime());
-            b.append("client", c.clientAddress() );
-            _appendUserInfo(currentOp, b, authSession);
-
-            b.append("err", "profile line too large (max is 100KB)");
-
-            // should be much smaller but if not don't break anything
-            if (small.size() < MAX_PROFILE_DOC_SIZE_BYTES){
-                b.append("abbreviated", small);
-            }
-
-            p = b.done();
-        }
-
         WriteUnitOfWork wunit(txn);
 
         // write: not replicated
diff --git a/src/mongo/dbtests/profile_test.cpp b/src/mongo/dbtests/profile_test.cpp
deleted file mode 100644
index 0f773933936..00000000000
--- a/src/mongo/dbtests/profile_test.cpp
+++ /dev/null
@@ -1,129 +0,0 @@
-/**
- *    Copyright (C) 2012 10gen Inc.
- *
- *    This program is free software: you can redistribute it and/or  modify
- *    it under the terms of the GNU Affero General Public License, version 3,
- *    as published by the Free Software Foundation.
- *
- *    This program is distributed in the hope that it will be useful,
- *    but WITHOUT ANY WARRANTY; without even the implied warranty of
- *    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
- *    GNU Affero General Public License for more details.
- *
- *    You should have received a copy of the GNU Affero General Public License
- *    along with this program.  If not, see <http://www.gnu.org/licenses/>.
- *
- *    As a special exception, the copyright holders give permission to link the
- *    code of portions of this program with the OpenSSL library under certain
- *    conditions as described in each individual source file and distribute
- *    linked combinations including the program with the OpenSSL library. You
- *    must comply with the GNU Affero General Public License in all respects
- *    for all of the code used other than as permitted herein. If you modify
- *    file(s) with this exception, you may extend this exception to your
- *    version of the file(s), but you are not obligated to do so. If you do not
- *    wish to do so, delete this exception statement from your version. If you
- *    delete this exception statement from all source files in the program,
- *    then also delete it in the license file.
- */
-
-/**
- * This file contains tests for the profile command
- */
-
-#include "mongo/db/dbdirectclient.h"
-#include "mongo/db/operation_context_impl.h"
-#include "mongo/unittest/unittest.h"
-
-using mongo::BSONObj;
-using mongo::DBDirectClient;
-
-using std::string;
-
-namespace mongo {
-
-    class Profiler: public mongo::unittest::Test {
-    public:
-        static const string PROFILER_TEST_DB;
-        static const string PROFILER_TEST_NS;
-        static const string PROFILE_NS;
-
-    protected:
-        void setUp() {
-            BSONObj ret;
-
-            OperationContextImpl txn;
-            DBDirectClient db(&txn);
-
-            db.runCommand(PROFILER_TEST_DB, BSON("dropDatabase" << 1), ret);
-            ASSERT(ret["ok"].trueValue());
-        }
-    };
-
-    const string Profiler::PROFILER_TEST_DB = "profilerTestDB";
-    const string Profiler::PROFILER_TEST_NS = Profiler::PROFILER_TEST_DB + ".test";
-    const string Profiler::PROFILE_NS = Profiler::PROFILER_TEST_DB + ".system.profile";
-
-    TEST_F(Profiler, BigDoc) {
-        // Test that update with large document with a long string can be
-        // be profiled in a shortened version
-        const string bigStr(16 * (1 << 20) - 200, 'a');
-
-        OperationContextImpl txn;
-        DBDirectClient db(&txn);
-
-        {
-            BSONObj replyObj;
-            db.runCommand(PROFILER_TEST_DB, BSON("profile" << 2), replyObj);
-            ASSERT(replyObj["ok"].trueValue());
-        }
-
-        const BSONObj doc(BSON("field" << bigStr));
-        db.update(PROFILER_TEST_NS, doc, doc);
-
-        std::auto_ptr<mongo::DBClientCursor> cursor = db.query(PROFILE_NS, BSONObj());
-        ASSERT(cursor->more());
-
-        BSONObj profileDoc(cursor->next());
-        ASSERT(profileDoc.hasField("abbreviated"));
-        const string abbreviatedField(profileDoc["abbreviated"].str());
-
-        // Make sure that the abbreviated field contains the query and the updateobj info
-        ASSERT(abbreviatedField.find("query:") != string::npos);
-        ASSERT(abbreviatedField.find("updateobj:") != string::npos);
-    }
-
-    TEST_F(Profiler, BigDocWithManyFields) {
-        // Test that update with large document with lots of fields can be
-        // be profiled in a shortened version
-        mongo::BSONObjBuilder builder;
-
-        for (int x = 0; x < (1 << 20); x++) {
-            const string fieldName(mongo::str::stream() << "x" << x);
-            builder.append(fieldName, x);
-        }
-
-        OperationContextImpl txn;
-        DBDirectClient db(&txn);
-
-        {
-            BSONObj replyObj;
-            db.runCommand(PROFILER_TEST_DB, BSON("profile" << 2), replyObj);
-            ASSERT(replyObj["ok"].trueValue());
-        }
-
-        const BSONObj doc(builder.done());
-        db.update(PROFILER_TEST_NS, doc, doc);
-
-        std::auto_ptr<mongo::DBClientCursor> cursor = db.query(PROFILE_NS, BSONObj());
-        ASSERT(cursor->more());
-
-        BSONObj profileDoc(cursor->next());
-        ASSERT(profileDoc.hasField("abbreviated"));
-        const string abbreviatedField(profileDoc["abbreviated"].str());
-
-        // Make sure that the abbreviated field contains the query and the updateobj info
-        ASSERT(abbreviatedField.find("query:") != string::npos);
-        ASSERT(abbreviatedField.find("updateobj:") != string::npos);
-    }
-}
-