Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-89293

Possible to double-count query (and possible other) metrics due to internal operations run on behalf of a user operation

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Unresolved
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: None
    • Server Programmability
    • ALL

      As part of parsing a find command, we will do an internal query on system.js.

      This internal query, if killed due to maxTimeMS, will increment the counter killedDueToMaxTimeMSExpired, adding to the counter for the user's query. It is technically true that two queries were killed here, but I don't think this is the intent for a metric to expose to customers.

      It's also worth auditing internal operations triggered by user-facing operations to make sure we aren't counting one operation as multiple elsewhere.

      #0  mongo::(anonymous namespace)::InBoth::record (this=<optimized out>, opCtx=0x315fbfbd7e00) at src/mongo/db/curop_metrics.cpp:86
#1  mongo::(anonymous namespace)::InShard::record (this=<optimized out>, opCtx=0x315fbfbd7e00) at src/mongo/db/curop_metrics.cpp:114
#2  mongo::recordCurOpMetrics (opCtx=opCtx@entry=0x315fbfbd7e00) at src/mongo/db/curop_metrics.cpp:164
#3  0x0000ffffdf59bca0 in mongo::(anonymous namespace)::HandleRequest::completeOperation (this=0xffffc5e687c0, response=...) at src/mongo/db/service_entry_point_common.cpp:2409
#4  mongo::ServiceEntryPointCommon::handleRequest (opCtx=<optimized out>, m=..., behaviors=...) at src/mongo/db/service_entry_point_common.cpp:2461
#5  0x0000ffffe8542d88 in mongo::(anonymous namespace)::loopbackBuildResponse (opCtx=0x315fbfbd7e00, toSend=...) at src/mongo/db/dbdirectclient.cpp:151
#6  0x0000ffffe8542c2c in mongo::DBDirectClient::_call (this=<optimized out>, toSend=..., actualServer=<optimized out>) at src/mongo/db/dbdirectclient.cpp:156
#7  0x0000ffffe72e4e78 in mongo::DBClientBase::call (this=0xffffc5e689d8, toSend=..., actualServer=0x0) at src/mongo/client/dbclient_base.h:495
#8  mongo::DBClientCursor::init (this=0x315fb94b7900) at src/mongo/client/dbclient_cursor.cpp:152
#9  0x0000ffffe72d42c4 in mongo::DBClientBase::find (this=<optimized out>, findRequest=..., readPref=..., exhaustMode=<optimized out>) at src/mongo/client/dbclient_base.cpp:570
#10 0x0000ffffe85434dc in mongo::DBDirectClient::find (this=0x315fbf858300, findRequest=..., readPref=..., exhaustMode=mongo::ExhaustMode::kOff) at src/mongo/db/dbdirectclient.cpp:184
#11 0x0000fffff23da2e8 in mongo::DBClientBase::find (this=0x315fbf858300, findRequest=..., readPref=...) at src/mongo/client/dbclient_base.h:528
#12 0x0000ffffe9fdd6c8 in mongo::Scope::loadStored (this=0x315fb9994240, opCtx=<optimized out>, ignoreNotConnected=<optimized out>) at src/mongo/scripting/engine.cpp:271
#13 0x0000ffffe9fdf400 in mongo::ScriptEngine::getPooledScope (this=<optimized out>, opCtx=<optimized out>, db=..., scopeType=...) at src/mongo/scripting/engine.cpp:644
#14 0x0000ffffea025350 in mongo::JsFunction::_init (this=this@entry=0x315fbf969950, opCtx=0x315fbfbd7e00, code="", dbName=...) at src/mongo/db/exec/js_function.cpp:91
#15 0x0000ffffea024f0c in mongo::JsFunction::JsFunction (this=<optimized out>, opCtx=0x315fbfaacf28, code=..., dbName=<error reading variable: Cannot access memory at address 0x18>) at src/mongo/db/exec/js_function.cpp:68
#16 0x0000fffff00d34a4 in std::make_unique<mongo::JsFunction, mongo::OperationContext* const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, mongo::DatabaseName const&> (__args="test.test", __args="test.test", __args="test.test") at /opt/mongodbtoolchain/revisions/69f4f0673ffcb290ce2307560a4883ecf2ad138c/stow/gcc-v4.liy/lib/gcc/aarch64-mongodb-linux/11.3.0/../../../../include/c++/11.3.0/bits/unique_ptr.h:962
#17 0x0000fffff00d306c in mongo::WhereMatchExpression::WhereMatchExpression (this=0x315fbf998cc0, opCtx=<optimized out>, params=..., dbName=...) at src/mongo/db/matcher/expression_where.cpp:50
#18 0x0000fffff00cc658 in std::make_unique<mongo::WhereMatchExpression, mongo::OperationContext* const&, mongo::WhereMatchExpressionBase::WhereParams, mongo::DatabaseName const&> (__args=..., __args=..., __args=...) at /opt/mongodbtoolchain/revisions/69f4f0673ffcb290ce2307560a4883ecf2ad138c/stow/gcc-v4.liy/lib/gcc/aarch64-mongodb-linux/11.3.0/../../../../include/c++/11.3.0/bits/unique_ptr.h:962
#19 mongo::ExtensionsCallbackReal::createWhere (this=<optimized out>, expCtx=..., where=...) at src/mongo/db/matcher/extensions_callback_real.cpp:82
#20 0x0000ffffea7f7ca4 in mongo::ExtensionsCallback::parseWhere (this=0xffffc5e6b998, expCtx=0x315fb9ad2380 = {...}, where=...) at src/mongo/db/matcher/extensions_callback.cpp:145
#21 0x0000ffffea7c0890 in std::function<mongo::StatusWith<std::unique_ptr<mongo::MatchExpression, std::default_delete<mongo::MatchExpression> > > (mongo::StringData, mongo::BSONElement, boost::intrusive_ptr<mongo::ExpressionContext> const&, mongo::ExtensionsCallback const*, unsigned long long, mongo::DocumentParseLevel)>::operator()(mongo::StringData, mongo::BSONElement, boost::intrusive_ptr<mongo::ExpressionContext> const&, mongo::ExtensionsCallback const*, unsigned long long, mongo::DocumentParseLevel) const (this=0xffffc5e6b240, __args=mongo::DocumentParseLevel::kPredicateTopLevel, __args=mongo::DocumentParseLevel::kPredicateTopLevel, __args=mongo::DocumentParseLevel::kPredicateTopLevel, __args=mongo::DocumentParseLevel::kPredicateTopLevel, __args=mongo::DocumentParseLevel::kPredicateTopLevel, __args=mongo::DocumentParseLevel::kPredicateTopLevel) at /opt/mongodbtoolchain/revisions/69f4f0673ffcb290ce2307560a4883ecf2ad138c/stow/gcc-v4.liy/lib/gcc/aarch64-mongodb-linux/11.3.0/../../../../include/c++/11.3.0/bits/std_function.h:590
#22 mongo::(anonymous namespace)::parse (obj=..., expCtx=0x315fb9ad2380 = {...}, extensionsCallback=0xffffc5e6b998, allowedFeatures=18446744073709551615, currentLevel=mongo::DocumentParseLevel::kPredicateTopLevel) at src/mongo/db/matcher/expression_parser.cpp:408
#23 0x0000ffffea7c062c in mongo::MatchExpressionParser::parse (obj=<error reading variable: Cannot access memory at address 0x315fc0000000>..., expCtx=uninitialized, extensionsCallback=..., allowedFeatures=1) at src/mongo/db/matcher/expression_parser.cpp:2156
#24 0x0000ffffee3408e4 in mongo::(anonymous namespace)::parseWithValidatedCollator (expCtx=0x315fb9ad2380 = {...}, findCommand=std::unique_ptr<mongo::FindCommandRequest> = {...}, extensionsCallback=..., allowedFeatures=18446744073709551615, projectionPolicies=...) at src/mongo/db/query/parsed_find_command.cpp:184
#25 mongo::parsed_find_command::parse (expCtx=0x315fb9ad2380 = {...}, params=...) at src/mongo/db/query/parsed_find_command.cpp:341
#26 0x0000ffffde560158 in mongo::(anonymous namespace)::parseQueryAndBeginOperation (opCtx=0x315fbfbd7e00, collOrViewAcquisition=..., nss="test.test", requestBody=owned BSONObj 152 bytes @ 0x315fbfe72f1d = {...}, findCommand=std::unique_ptr<mongo::FindCommandRequest> = {...}) at src/mongo/db/commands/find_cmd.cpp:216
#27 mongo::(anonymous namespace)::FindCmd::Invocation::run (this=0x315fbf91d430, opCtx=<optimized out>, replyBuilder=0x315fbf997130) at src/mongo/db/commands/find_cmd.cpp:714
#28 0x0000ffffe88b0a48 in mongo::CommandHelpers::runCommandInvocation (opCtx=0x315fbfbd7e00, request=..., invocation=<optimized out>, response=<optimized out>) at src/mongo/db/commands.cpp:199
#29 0x0000ffffdf5a5f1c in mongo::(anonymous namespace)::runCommandInvocation (rec=..., invocation=0x315fbf91d430) at src/mongo/db/service_entry_point_common.cpp:218
#30 mongo::(anonymous namespace)::InvokeCommand::run (this=<optimized out>) at src/mongo/db/service_entry_point_common.cpp:813
#31 mongo::(anonymous namespace)::RunCommandImpl::_runCommand (this=<optimized out>) at src/mongo/db/service_entry_point_common.cpp:1265
#32 0x0000ffffdf5a44b4 in mongo::(anonymous namespace)::RunCommandImpl::run()::{lambda()#1}::operator()() const (this=<optimized out>) at src/mongo/db/service_entry_point_common.cpp:690
#33 mongo::(anonymous namespace)::RunCommandImpl::run (this=this@entry=0xffffc5e6c330) at src/mongo/db/service_entry_point_common.cpp:687
#34 0x0000ffffdf5a1cf8 in mongo::(anonymous namespace)::ExecCommandDatabase::_commandExec (this=this@entry=0xffffc5e6c910) at src/mongo/db/service_entry_point_common.cpp:1960
#35 0x0000ffffdf5a06e4 in mongo::(anonymous namespace)::ExecCommandDatabase::run()::{lambda()#1}::operator()() const (this=<optimized out>) at src/mongo/db/service_entry_point_common.cpp:505
#36 mongo::(anonymous namespace)::ExecCommandDatabase::run (this=this@entry=0xffffc5e6c910) at src/mongo/db/service_entry_point_common.cpp:502
#37 0x0000ffffdf59d41c in mongo::(anonymous namespace)::executeCommand (execContext=...) at src/mongo/db/service_entry_point_common.cpp:2212
#38 mongo::(anonymous namespace)::receivedCommands (execContext=...) at src/mongo/db/service_entry_point_common.cpp:2284
#39 0x0000ffffdf59b710 in mongo::(anonymous namespace)::HandleRequest::runOperation (this=0xffffc5e6d440) at src/mongo/db/service_entry_point_common.cpp:2349

            Assignee:
            Unassigned Unassigned
            Reporter:
            yuhong.zhang@mongodb.com Yuhong Zhang
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated: