[SERVER-23331] Add cursorID and ConnectionID to system.profile documents Created: 24/Mar/16  Updated: 06/Feb/19  Resolved: 06/Feb/19

Status: Closed
Project: Core Server
Component/s: Diagnostics, Logging
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: Shakir Sadikali Assignee: Asya Kamsky
Resolution: Done Votes: 2
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

In 3.2 I get the following.

MongoDB Enterprise > db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty()
{
	"op" : "query",
	"ns" : "test.testcol",
	"query" : {
		"find" : "testcol",
		"filter" : {
			
		}
	},
	"keysExamined" : 0,
	"docsExamined" : 1,
	"cursorExhausted" : true,
	"keyUpdates" : 0,
	"writeConflicts" : 0,
	"numYield" : 0,
	"locks" : {
		"Global" : {
			"acquireCount" : {
				"r" : NumberLong(2)
			}
		},
		"Database" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		},
		"Collection" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		}
	},
	"nreturned" : 1,
	"responseLength" : 139,
	"protocol" : "op_command",
	"millis" : 0,
	"execStats" : {
		"stage" : "COLLSCAN",
		"filter" : {
			"$and" : [ ]
		},
		"nReturned" : 1,
		"executionTimeMillisEstimate" : 0,
		"works" : 3,
		"advanced" : 1,
		"needTime" : 1,
		"needYield" : 0,
		"saveState" : 0,
		"restoreState" : 0,
		"isEOF" : 1,
		"invalidates" : 0,
		"direction" : "forward",
		"docsExamined" : 1
	},
	"ts" : ISODate("2016-03-24T14:09:40.200Z"),
	"client" : "127.0.0.1",
	"allUsers" : [ ],
	"user" : ""
}

I know "cursorExhausted" : true means the cursor was consumed. I would like to capture the ID regardless. I want to be able to take a slow query from the mongod.log and get deeper stats on it without having to parse and do complicated queries. My colleague did a getmore and got:

{
    "op" : "getmore",
    "ns" : "test.test",
    "query" : {
        "getMore" : NumberLong("32613554020"),
        "collection" : "test"
    },
    "cursorid" : 32613554020,
    "cursorExhausted" : true,
    "keyUpdates" : 0,
    "writeConflicts" : 0,
    "numYield" : 7,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(16)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(8)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "r" : NumberLong(8)
            }
        }
    },
    "nreturned" : 899,
    "responseLength" : 34133,
    "protocol" : "op_command",
    "millis" : 3,
    "execStats" : {
        
    },
    "ts" : ISODate("2016-03-24T13:58:47.891Z"),
    "client" : "127.0.0.1",
    "allUsers" : [ ],
    "user" : ""
}

I'd like the output to be consistent, to capture the cursorID in all cases to be able to compare to the mongod.log and to also be able to use the system.profile for diagnostics.



 Comments   
Comment by Asya Kamsky [ 06/Feb/19 ]

I'm going to close this ticket because I believe we provide this information in the current version:

{
	"op" : "command",
	"ns" : "views.foo",
	"command" : {
		"aggregate" : "foo",
		"pipeline" : [
                    ...		],
		"cursor" : {
 
		},
		"$db" : "views"
	},
	"cursorid" : NumberLong("8579475506467892867"),
	"keysExamined" : 0,
	"docsExamined" : 4,
	"numYield" : 0,
	"nreturned" : 101,
        ...
},
{
	"op" : "getmore",
	"ns" : "views.foo",
	"command" : {
		"getMore" : NumberLong("8579475506467892867"),
		"collection" : "foo",
		"$db" : "views"
	},
	"originatingCommand" : {
		"aggregate" : "foo",
		"pipeline" : [
                 ...
		],
		"cursor" : {
 
		},
		"$db" : "views"
	},
	"cursorid" : NumberLong("8579475506467892867"),
	"keysExamined" : 0,
	"docsExamined" : 0,
	"cursorExhausted" : true,
	"numYield" : 0,
	"nreturned" : 3899,
        ...
}

Same thing is visible in the logs.

Comment by James Wahlin [ 25/Jan/19 ]

The cursorid field is also profiled with a find command that generates a cursor.

Comment by James Wahlin [ 25/Jan/19 ]

The cursorid for a getMore command is currently be written to the profiler:

{
	"op" : "getmore",
	"ns" : "profile_getmore.test",
	"command" : {
		"getMore" : NumberLong("8151990459365062301"),
		"collection" : "test",
		"batchSize" : 2,
		"lsid" : {
			"id" : UUID("4c68e4d9-e098-4fde-843a-6f62e0ccfacf")
		},
		"$db" : "profile_getmore"
	},
	"originatingCommand" : {
		"find" : "test",
		"filter" : {
			"a" : {
				"$gt" : 0
			}
		},
		"batchSize" : 2,
		"sort" : {
			"a" : 1
		},
		"lsid" : {
			"id" : UUID("4c68e4d9-e098-4fde-843a-6f62e0ccfacf")
		},
		"$db" : "profile_getmore"
	},
	"cursorid" : NumberLong("8151990459365062301"),
	"keysExamined" : 2,
	"docsExamined" : 2,
	"numYield" : 0,
	"nreturned" : 2,
	"locks" : {
		"Global" : {
			"acquireCount" : {
				"r" : NumberLong(1),
				"w" : NumberLong(1)
			}
		},
		"Database" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		},
		"Collection" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		}
	},
	"responseLength" : 180,
	"protocol" : "op_msg",
	"millis" : 0,
	"planSummary" : "IXSCAN { a: 1 }",
	"execStats" : {
		"stage" : "FETCH",
		"nReturned" : 4,
		"executionTimeMillisEstimate" : 10,
		"works" : 4,
		"advanced" : 4,
		"needTime" : 0,
		"needYield" : 0,
		"saveState" : 1,
		"restoreState" : 1,
		"isEOF" : 0,
		"docsExamined" : 4,
		"alreadyHasObj" : 0,
		"inputStage" : {
			"stage" : "IXSCAN",
			"nReturned" : 4,
			"executionTimeMillisEstimate" : 10,
			"works" : 4,
			"advanced" : 4,
			"needTime" : 0,
			"needYield" : 0,
			"saveState" : 1,
			"restoreState" : 1,
			"isEOF" : 0,
			"keyPattern" : {
				"a" : 1
			},
			"indexName" : "a_1",
			"isMultiKey" : false,
			"multiKeyPaths" : {
				"a" : [ ]
			},
			"isUnique" : false,
			"isSparse" : false,
			"isPartial" : false,
			"indexVersion" : 2,
			"direction" : "forward",
			"indexBounds" : {
				"a" : [
					"(0.0, inf.0]"
				]
			},
			"keysExamined" : 4,
			"seeks" : 1,
			"dupsTested" : 0,
			"dupsDropped" : 0
		}
	},
	"ts" : ISODate("2019-01-25T20:25:15.626Z"),
	"client" : "127.0.0.1",
	"appName" : "MongoDB Shell",
	"allUsers" : [ ],
	"user" : ""
}

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