[SERVER-16265] Add query details to getmore entry in profiler and db.currentOp() Created: 21/Nov/14  Updated: 13/Dec/17  Resolved: 20/May/15

Status: Closed
Project: Core Server
Component/s: Diagnostics, Querying
Affects Version/s: None
Fix Version/s: 2.6.11, 3.0.4, 3.1.4

Type: Improvement Priority: Major - P3
Reporter: Jon Rangel (Inactive) Assignee: David Storch
Resolution: Done Votes: 4
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Documented
is documented by DOCS-5482 Document changes to db.currentOp() / ... Closed
Related
related to SERVER-16847 Diagnostic log output for all query c... Closed
related to SERVER-17716 Correlate the parts of distributed op... Closed
related to SERVER-17862 Unify stats reporting for log/profile... Closed
is related to SERVER-4045 Display queries for getmore ops in db... Closed
Backwards Compatibility: Fully Compatible
Backport Completed:
Sprint: Quint Iteration 4
Participants:
Case:

 Description   

It is possible to run aggregation queries with the {cursor:{batchSize:0}} option, in order to quickly get back a cursor that can subsequently be iterated. This approach is documented here.
The problem with using this option is that it makes debugging slow queries difficult since the database profiler (set to level 1) and mongod logs only record the 'getmore' ops on the cursor, since the original query is very fast.
I think a couple of enhancements are needed :

  • add details of the query to the getmore log entry (which is essential for the above case)
  • add the details of the query to db.currentOp()
  • add the cursorId to the original query log entry (which makes correlating a query and its associated getmores much easier)


 Comments   
Comment by David Storch [ 20/Sep/16 ]

Hi admin@mixmax.com,

The upcoming MongoDB 3.4 release will contain a number of improvements to the diagnostics reported in system.profile, the slow query logs, and db.currentOp(). The umbrella ticket for these changes is SERVER-17862, which summarizes the incorporated fixes.

Regarding your specific question about getMore, SERVER-23260 added a field called originatingCommand which should help you trace back from a getMore to the command which created the cursor.

Best,
Dave

Comment by Brad Vogel [ 20/Sep/16 ]

Hi - I see that db.currentOp() now reveals the original query, but the slow query log still only reveals only that it is a `getmore` query:

{ "op" : "getmore", "ns" : "app-prod.snippets", "query" : { "getMore" :

{ "$numberLong" : "207536363671" }

, "collection" : "snippets", "batchSize" :

{ "$numberLong" : "0" }

}, "cursorid" :

{ "$numberLong" : "207536363671" }

, "cursorExhausted" : true, "keyUpdates" : 0, "writeConflicts" : 0, "numYield" : 697, "locks" : { "Global" : { "acquireCount" : { "r" :

{ "$numberLong" : "1396" }

} }, "Database" : { "acquireCount" : { "r" :

{ "$numberLong" : "698" }

} }, "Collection" : { "acquireCount" : { "r" :

{ "$numberLong" : "698" }

} } }, "nreturned" : 52212, "responseLength" : 3317968, "millis" : 38431, "execStats" : { }, "ts" :

{ "$date" : "2016-09-20T00:36:01.962+0000" }

, "client" : "54.197.6.67", "allUsers" : [

{ "user" : "app", "db" : "admin" }

], "user" : "app@admin" }

How can I figure out the original query from the above getmore?

Comment by Githook User [ 20/May/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-16265 add query predicate and aggregation command to the getMore slow query log / profile entries

(cherry picked from commit d89e58fd340ced9370d1a39a4334a42a77005f5e)

Conflicts:
src/mongo/db/commands/pipeline_command.cpp
src/mongo/db/query/find.cpp
Branch: v2.6
https://github.com/mongodb/mongo/commit/3e43c6efd8580ccc155e822d3d37dbc115494bc1

Comment by Githook User [ 20/May/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-16265 add query predicate and aggregation command to the getMore slow query log / profile entries

(cherry picked from commit d89e58fd340ced9370d1a39a4334a42a77005f5e)
Branch: v3.0
https://github.com/mongodb/mongo/commit/b4ad028972a125bdf52b775fb1daa42df0359fc1

Comment by Githook User [ 20/May/15 ]

Author:

{u'username': u'dstorch', u'name': u'David Storch', u'email': u'david.storch@10gen.com'}

Message: SERVER-16265 add query predicate and aggregation command to the getMore slow query log / profile entries
Branch: master
https://github.com/mongodb/mongo/commit/d89e58fd340ced9370d1a39a4334a42a77005f5e

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