mongo/jstests/core/profile4.js

/**
 * Check debug information recorded for a query.
 */

function profileCursor() {
    var userStr = username + "@" + db.getName();
    return db.system.profile.find({user: userStr});
}

function getLastOp() {
    return profileCursor().sort({$natural: -1}).next();
}

// Special db so that it can be run in parallel tests. Also need to create a user so that
// operations run by this test (and not other tests running in parallel) can be identified.
var stddb = db;
var db = db.getSisterDB("profile4");

db.dropAllUsers();
var coll = db.profile4;
coll.drop();

var username = "jstests_profile4_user";
db.createUser({user: username, pwd: "password", roles: jsTest.basicUserRoles});
db.auth(username, "password");

try {
    var lastOp;

    // Clear the profiling collection.
    db.setProfilingLevel(0);
    db.system.profile.drop();
    assert.eq(0 , profileCursor().count());

    // Enable profiling. It will be disabled again at the end of the test, or if the test fails.
    db.setProfilingLevel(2);

    coll.find().itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.op, "query");
    assert.eq(lastOp.query.find, coll.getName());
    assert.eq(lastOp.ns, coll.getFullName());
    assert.eq(lastOp.keysExamined, 0);
    assert.eq(lastOp.keyUpdates, 0);
    assert.eq(lastOp.nreturned, 0);
    assert.eq(lastOp.cursorExhausted, true);

    // Check write lock stats are set.
    coll.save({});
    lastOp = getLastOp();
    assert.eq(lastOp.op, "insert");
    assert.lt(0, Object.keys(lastOp.locks).length);

    // Check read lock stats are set.
    coll.find();
    lastOp = getLastOp();
    assert.eq(lastOp.op, "query");
    assert.lt(0, Object.keys(lastOp.locks).length);

    coll.save({});
    coll.save({});
    coll.find().skip(1).limit(4).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.skip, 1)
    assert.eq(lastOp.docsExamined, 3);
    assert.eq(lastOp.nreturned, 2);
    // Find command will use "limit", OP_QUERY will use ntoreturn.
    var expectedField = db.getMongo().useReadCommands() ? "limit" : "ntoreturn";
    assert.eq(lastOp.query[expectedField], 4);

    coll.find().batchSize(2).next();
    lastOp = getLastOp();
    assert.lt(0, lastOp.cursorid);

    coll.find({a: 1}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.filter, {a: 1});

    coll.find({_id: 0}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.idhack, true);

    coll.find().sort({a: 1}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.hasSortStage, true);

    coll.ensureIndex({a: 1});
    coll.find({a: 1}).itcount();
    lastOp = getLastOp();
    assert.eq("FETCH", lastOp.execStats.stage, tojson(lastOp.execStats));
    assert.eq("IXSCAN", lastOp.execStats.inputStage.stage, tojson(lastOp.execStats));

    // For queries with a lot of stats data, the execution stats in the profile is replaced by
    // the plan summary.
    var orClauses = 32;
    var bigOrQuery = { $or: [] };
    for (var i = 0; i < orClauses; ++i) {
        var indexSpec = {};
        indexSpec["a" + i] = 1;
        coll.ensureIndex(indexSpec);
        bigOrQuery["$or"].push(indexSpec);
    }
    coll.find(bigOrQuery).itcount();
    lastOp = getLastOp();
    assert.neq(undefined, lastOp.execStats.summary, tojson(lastOp.execStats));

    // Confirm "cursorExhausted" not set when cursor is open.
    coll.drop();
    coll.insert([{_id: 0}, {_id: 1}, {_id: 2}, {_id: 3}, {_id: 4}]);
    coll.find().batchSize(2).next(); // Query performed leaving open cursor
    lastOp = getLastOp();
    assert.eq(lastOp.op, "query");
    assert(!("cursorExhausted" in lastOp));

    var cursor = coll.find().batchSize(2);
    cursor.next(); // Perform initial query and consume first of 2 docs returned.
    cursor.next(); // Consume second of 2 docs from initial query.
    cursor.next(); // getMore performed, leaving open cursor.
    lastOp = getLastOp();
    assert.eq(lastOp.op, "getmore");
    assert(!("cursorExhausted" in lastOp));

    // Exhaust cursor and confirm getMore has "cursorExhausted:true".
    cursor.itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.cursorExhausted, true);

    // OP_QUERY-specific test for the "wrapped" query predicate form.
    if (!db.getMongo().useReadCommands()) {
        // Must accept non-dollar-prefixed forms of "query" and "orderby".
        coll.find({query: {_id: {$gte: 0}}, orderby: {_id: 1}}).itcount();
        lastOp = getLastOp();
        assert.eq(lastOp.op, "query");
        assert.eq(lastOp.query.find, coll.getName());
        assert.eq(lastOp.query.filter, {_id: {$gte: 0}});
        assert.eq(lastOp.query.sort, {_id: 1});

        // Should also work with dollar-prefixed forms.
        coll.find({$query: {_id: {$gte: 0}}, $orderby: {_id: 1}}).itcount();
        lastOp = getLastOp();
        assert.eq(lastOp.op, "query");
        assert.eq(lastOp.query.find, coll.getName());
        assert.eq(lastOp.query.filter, {_id: {$gte: 0}});
        assert.eq(lastOp.query.sort, {_id: 1});

        // Negative ntoreturn.
        coll.find().limit(-3).itcount();
        lastOp = getLastOp();
        assert.eq(lastOp.query.ntoreturn, -3);
    }

    // getMore command should show up as a getMore operation, not a command.
    var cmdRes = db.runCommand({find: coll.getName(), batchSize: 1});
    assert.commandWorked(cmdRes);
    db.runCommand({getMore: cmdRes.cursor.id, collection: coll.getName()});
    lastOp = getLastOp();
    assert.eq(lastOp.op, "getmore");
    assert.eq(lastOp.ns, coll.getFullName());

    // getMore entry created by iterating the cursor should have the same format, regardless of
    // readMode.
    coll.find().batchSize(3).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.op, "getmore");
    assert.eq(lastOp.ns, coll.getFullName());
    assert("getMore" in lastOp.query);
    assert.eq(lastOp.query.getMore, lastOp.cursorid);
    assert.eq(lastOp.query.collection, coll.getName());
    assert.eq(lastOp.query.batchSize, 3)
    assert.eq(lastOp.cursorExhausted, true)
    assert.eq(lastOp.nreturned, 2);
    assert("responseLength" in lastOp);

    // Ensure that special $-prefixed OP_QUERY options like $hint and $returnKey get added to the
    // profiler entry correctly.
    coll.find().hint({_id: 1}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.hint, {_id: 1});

    coll.find().comment("a comment").itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.comment, "a comment");

    coll.find().maxScan(3000).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.maxScan, 3000);

    coll.find().maxTimeMS(4000).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.maxTimeMS, 4000);

    coll.find().max({_id: 3}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.max, {_id: 3});

    coll.find().min({_id: 0}).itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.min, {_id: 0});

    coll.find().returnKey().itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.returnKey, true);

    coll.find().snapshot().itcount();
    lastOp = getLastOp();
    assert.eq(lastOp.query.snapshot, true);

    db.setProfilingLevel(0);
    db.system.profile.drop();
}
finally {
    db.setProfilingLevel(0);
    db = stddb;
}