[SERVER-9222] On explain() millis value is 0 for GeoSearchCursor Created: 03/Apr/13  Updated: 10/Dec/14  Resolved: 02/Jan/14

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: 2.2.3
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Aurelien Beltrame Assignee: Unassigned
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

linux ubuntu 12.04


Issue Links:
Duplicate
duplicates SERVER-12231 explain() for GeoSearchCursor broken Closed
Related
Operating System: ALL
Participants:

 Description   

On some small fast query with geoSearchCursor, millis always return 0 inside explain() / explain(true) result.

To ensure the query is not so fast, then I activate the profiling and query stay at millis:0 in front but at 50 ms in profiling collection (which is slow but more or less what I expected).



 Comments   
Comment by Daniel Pasette (Inactive) [ 02/Jan/14 ]

Duplicate of SERVER-12231, which enlarges the scope of the ticket a bit.

Comment by Aurelien Beltrame [ 16/Apr/13 ]

I try a simple find() on a collection with thousands documents. Explain provide a value != 0 (I try differents collections (=> differents # docs) to get queries with 20-50 ms).

Comment by Andre de Frere [ 16/Apr/13 ]

Hi,

You specifically mention the geoSearchCursor. Are you seeing this issue only on geo queries, or do you see the same pattern on all fast queries?

From the profile output it appears that the query is spending all of it's time a read lock, which could be indicative of reading data and filling the network buffer.

Comment by Aurelien Beltrame [ 04/Apr/13 ]

(sorry for layout. I hide database/collection name.)

the index called cpd_sparse :

{
                "v" : 1,
                "key" : {
                        "geo" : "2d",
                        "specific" : 1
                },
                "ns" : "myDb.myCollection",
                "name" : "cpd_sparse",
                "sparse" : true
        }

the query is :

 db.myCollection.find({geo: {$near: [40, 1] }, "specific":true}).limit(1).hint('cpd_sparse').sort({distance:1})

the explain

{
        "cursor" : "GeoSearchCursor",
        "isMultiKey" : false,
        "n" : 1,
        "nscannedObjects" : 1,
        "nscanned" : 1,
        "nscannedObjectsAllPlans" : 1,
        "nscannedAllPlans" : 1,
        "scanAndOrder" : true,
        "indexOnly" : false,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "millis" : 0,
        "indexBounds" : {
 
        },
        "allPlans" : [
                {
                        "cursor" : "GeoSearchCursor",
                        "n" : 1,
                        "nscannedObjects" : 1,
                        "nscanned" : 1,
                        "indexBounds" : {
 
                        }
                }
        ],
        "server" : "a-lpt:27017"
}

the profile output:

Date: 2013-04-04 10:10:39
{
   "ts": ISODate("2013-04-04T08: 10: 39.856Z"),
   "op": "query",
   "ns": "myDb.myCollection",
   "query": {
     "query": {
       "geo": {
         "$near": [
           40,
           1 
        ] 
      },
       "specific": true 
    },
     "$hint": "cpd_sparse",
     "orderby": {
       "distance": 1 
    } 
  },
   "ntoreturn": NumberInt(1),
   "ntoskip": NumberInt(0),
   "nscanned": NumberInt(1),
   "scanAndOrder": true,
   "keyUpdates": NumberInt(0),
   "numYield": NumberInt(0),
   "lockStats": {
     "timeLockedMicros": {
       "r": NumberLong(23155),
       "w": NumberLong(0) 
    },
     "timeAcquiringMicros": {
       "r": NumberLong(13),
       "w": NumberLong(4) 
    } 
  },
   "nreturned": NumberInt(1),
   "responseLength": NumberInt(583),
   "millis": NumberInt(23),
   "client": "127.0.0.1",
   "user": "" 
}

Comment by Eliot Horowitz (Inactive) [ 03/Apr/13 ]

Can you send an example query, the explain, and the profile output?

What's probably causing the difference is that the explain doesn't do the data copy to the network buffers, so just evaluating the query is fast, but when you do it for real there is copying to be done.

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