[SERVER-21855] Certain commands are never captured in system profiler Created: 10/Dec/15  Updated: 06/Dec/22

Status: Backlog
Project: Core Server
Component/s: Diagnostics
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: J Rassi Assignee: Backlog - Query Optimization
Resolution: Unresolved Votes: 0
Labels: query-44-grooming
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by SERVER-8539 Profiler omits operations which don't... Closed
Related
related to SERVER-21772 findAndModify not captured by Profiler Closed
is related to SERVER-17862 Unify stats reporting for log/profile... Closed
Assigned Teams:
Query Optimization
Operating System: ALL
Participants:

 Description   

Certain commands are never captured in the system profiler, regardless of the value of the global profiling level (as set by the --profile command line option) or the database profiling level (as set by the profile command).

Reproduce with following script, which runs a number of commands and then scrapes system.profile to determine which were profiled.

// Set up test.
assert.commandWorked(db.createCollection("foo"));
 
// Run commands on "test" database.
assert.commandWorked(db.runCommand({createIndexes: "foo", indexes: [{key: {a: 1}, name: "foo"}]}));
assert.commandWorked(db.runCommand("dbhash"));
assert.commandWorked(db.runCommand("listCollections"));
assert.commandWorked(db.runCommand({validate: "foo"}));
 
// Run commands on "admin" database.
assert.commandWorked(db.adminCommand({applyOps: []}));
assert.commandWorked(db.adminCommand("buildInfo"));
assert.commandWorked(db.adminCommand("connPoolStats"));
assert.commandWorked(db.adminCommand("currentOp"));
assert.commandWorked(db.adminCommand("features"));
assert.commandWorked(db.adminCommand("fsync"));
assert.commandWorked(db.adminCommand("getLastError"));
assert.commandWorked(db.adminCommand({getLog: "global"}));
assert.commandWorked(db.adminCommand({getParameter: "*"}));
assert.commandWorked(db.adminCommand("isMaster"));
assert.commandWorked(db.adminCommand("listCommands"));
assert.commandWorked(db.adminCommand("listDatabases"));
assert.commandWorked(db.adminCommand("logout"));
assert.commandWorked(db.adminCommand("ping"));
assert.commandWorked(db.adminCommand({profile: -1}));
assert.commandWorked(db.adminCommand("serverStatus"));
assert.commandWorked(db.adminCommand("top"));
assert.commandWorked(db.adminCommand("usersInfo"));
assert.commandWorked(db.adminCommand("whatsmyuri"));
 
// Scrape 'test.system.profile' and 'admin.system.profile' and output list of commands that were profiled.
var profileQuery = {command: {$exists: true}};
var profileEntries = [];
profileEntries = profileEntries.concat(db.system.profile.find(profileQuery).toArray());
profileEntries =
    profileEntries.concat(db.getSiblingDB("admin").system.profile.find(profileQuery).toArray());
profiledCommands = {};
for (var i = 0; i < profileEntries.length; i++) {
    for (elt in profileEntries[i].command) {
        profiledCommands[elt] = 1;
        break;
    }
}
for (command in profiledCommands) {
    print(command);
}

See the following shell session, which runs the above script against a 3.2.0 mongod instance started with --profile 2 (which enables profiling for all operations). No commands run by the script are profiled (with the exception of the create command used in the test setup).

rassi@rassi:~/work/mongo$ mongo --quiet repro.js
create
rassi@rassi:~/work/mongo$

Many commands have been affected by this issue since they were first introduced, though some have regressed over time. The following is a partial list of the regressions introduced over the past few major releases:

  • As of 2.3.1, top is no longer profiled.
  • As of 2.7.0, serverStatus, applyOps are no longer profiled.
  • As of 2.7.5, listCollections is no longer profiled.
  • As of 2.7.8, dbhash, listDatabases, getParameter are no longer profiled.
  • As of 2.8.0-rc0, createIndexes is no longer profiled.
  • As of 3.1.0, validate is no longer profiled.
  • As of 3.1.9, profile is no longer profiled.


 Comments   
Comment by J Rassi [ 21/Mar/16 ]

Note also that the eval command doesn't generate a profiler entry when run with the "nolock" option set, according to SERVER-8539. I'm on the fence about whether or not to recommend changing that command's behavior, or instead to apply the above proposed strategy ("updating our documentation to state that commands which do not acquire a database lock will not be profiled").

Comment by J Rassi [ 14/Jan/16 ]

milkie suggests updating our documentation to state that commands which do not acquire a database lock will not be profiled. This seems reasonable, to me.

To fix most of the remaining commands, I'd recommend an approach like the following:

  • Change the type of CurOp::_ns to be NamespaceString.
  • Remove the call to CurOp::enter_inlock() from the AutoGetCollectionForRead constructor.
  • In the constructors for AutoGetDb and AutoGetOrCreateDb, fill in the database name of CurOp::_ns and raise the profiling level appropriately.

That leaves a couple of special cases, createIndexes and applyOps:

  • The createIndexes command should be ported to use AutoGetOrCreateDb, or a call to CurOp::enter_inlock() should be added to its run() method.
  • The profiling story for applyOps command is somewhat complicated, since it affects multiple databases. It should probably raise the profiling level manually on the database specified in the command request header.

I suggest that we defer this work until progress on SERVER-17862 has started, since it is possible that we will schedule some relevant CurOp cleanup as part of the implementation of that work.

Comment by J Rassi [ 10/Dec/15 ]

This was discovered while investigating SERVER-21772.

As of current master, commands (with the exception of the write commands) will only be profiled if they explicitly use one of the following objects from db_raii.h:

  • AutoGetCollectionForRead
  • OldClientContext
  • OldClientWriteContext

This is because operations are never profiled unless they generate a call to CurOp::raiseDbProfileLevel(). The only callers of raiseDbProfileLevel() are the write commands batch executor and CurOp::enter_inlock(), and the only callers of CurOp::enter_inlock() are the constructors for the above three RAII objects.

Generated at Thu Feb 08 03:58:37 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.