[CSHARP-1442] C# driver does not honor limit when executing find Created: 14/Oct/15  Updated: 11/Feb/16  Resolved: 11/Feb/16

Status: Closed
Project: C# Driver
Component/s: Operations, Performance
Affects Version/s: 2.0.1
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: bothead Assignee: Robert Stam
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

.NET 4.5, Azure, Windows


Attachments: Zip Archive ConsoleApplication4.zip    

 Description   

I have been porting our repository layer to use the new driver (2.0.1), and in doing so we have noticed some performance degradation with the new driver. Upon investigating where we potentially went wrong I went back to the old code to capture the queries logged in the profiler database to compare against what is now being generated by the new driver.

NOTE: We are using database version 3.0.4.

In the queries generated by the new driver the LIMIT stage of the query is no longer honored, and thus not reported as part of the query execution plan.

(new driver code/log below...)

Legacy driver code:

                var query = Query<Tenant>.EQ(e => e.Name, name);
                var found = this.retryHandler.ExecuteFunc(() => this.Collection.FindOne(query));
                return found;

Logged in profiler database for legacy code:

{
    "op" : "query",
    "ns" : "dfl.tenants",
    "query" : {
        "Name" : "dev"
    },
    "ntoskip" : 0,
    "nscanned" : 1,
    "nscannedObjects" : 1,
    "keyUpdates" : 0,
    "writeConflicts" : 0,
    "numYield" : 0,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(2)
            }
        },
        "MMAPV1Journal" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "R" : NumberLong(1)
            }
        }
    },
    "nreturned" : 1,
    "responseLength" : 103,
    "millis" : 0,
    "execStats" : {
        "stage" : "LIMIT",
        "nReturned" : 1,
        "executionTimeMillisEstimate" : 0,
        "works" : 1,
        "advanced" : 1,
        "needTime" : 0,
        "needFetch" : 0,
        "saveState" : 0,
        "restoreState" : 0,
        "isEOF" : 1,
        "invalidates" : 0,
        "limitAmount" : 0,
        "inputStage" : {
            "stage" : "FETCH",
            "nReturned" : 1,
            "executionTimeMillisEstimate" : 0,
            "works" : 1,
            "advanced" : 1,
            "needTime" : 0,
            "needFetch" : 0,
            "saveState" : 0,
            "restoreState" : 0,
            "isEOF" : 1,
            "invalidates" : 0,
            "docsExamined" : 1,
            "alreadyHasObj" : 0,
            "inputStage" : {
                "stage" : "IXSCAN",
                "nReturned" : 1,
                "executionTimeMillisEstimate" : 0,
                "works" : 1,
                "advanced" : 1,
                "needTime" : 0,
                "needFetch" : 0,
                "saveState" : 0,
                "restoreState" : 0,
                "isEOF" : 1,
                "invalidates" : 0,
                "keyPattern" : {
                    "Name" : 1
                },
                "indexName" : "Name_1",
                "isMultiKey" : false,
                "direction" : "forward",
                "indexBounds" : {
                    "Name" : [ 
                        "[\"dev\", \"dev\"]"
                    ]
                },
                "keysExamined" : 1,
                "dupsTested" : 0,
                "dupsDropped" : 0,
                "seenInvalidated" : 0,
                "matchTested" : 0
            }
        }
    },
    "ts" : ISODate("2015-10-14T18:34:08.919Z"),
    "client" : "127.0.0.1",
    "allUsers" : [],
    "user" : ""
}

New driver code:

                var filter = Builders<Tenant>.Filter.Eq(e => e.Name, name);
                var find = this.Collection.Find(filter).Limit(1);
                return await this.retryHandler.ExecuteFuncAsync(() => find.SingleOrDefaultAsync()).ConfigureAwait(false);

Logged in profiler database for new code:

{
    "op" : "query",
    "ns" : "dfl.tenants",
    "query" : {
        "$query" : {
            "Name" : "dev"
        }
    },
    "ntoreturn" : 1,
    "ntoskip" : 0,
    "nscanned" : 1,
    "nscannedObjects" : 1,
    "keyUpdates" : 0,
    "writeConflicts" : 0,
    "numYield" : 0,
    "locks" : {
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(2)
            }
        },
        "MMAPV1Journal" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "R" : NumberLong(1)
            }
        }
    },
    "nreturned" : 1,
    "responseLength" : 103,
    "millis" : 0,
    "execStats" : {
        "stage" : "FETCH",
        "nReturned" : 1,
        "executionTimeMillisEstimate" : 0,
        "works" : 1,
        "advanced" : 1,
        "needTime" : 0,
        "needFetch" : 0,
        "saveState" : 0,
        "restoreState" : 0,
        "isEOF" : 1,
        "invalidates" : 0,
        "docsExamined" : 1,
        "alreadyHasObj" : 0,
        "inputStage" : {
            "stage" : "IXSCAN",
            "nReturned" : 1,
            "executionTimeMillisEstimate" : 0,
            "works" : 1,
            "advanced" : 1,
            "needTime" : 0,
            "needFetch" : 0,
            "saveState" : 0,
            "restoreState" : 0,
            "isEOF" : 1,
            "invalidates" : 0,
            "keyPattern" : {
                "Name" : 1
            },
            "indexName" : "Name_1",
            "isMultiKey" : false,
            "direction" : "forward",
            "indexBounds" : {
                "Name" : [ 
                    "[\"dev\", \"dev\"]"
                ]
            },
            "keysExamined" : 1,
            "dupsTested" : 0,
            "dupsDropped" : 0,
            "seenInvalidated" : 0,
            "matchTested" : 0
        }
    },
    "ts" : ISODate("2015-10-14T20:18:23.168Z"),
    "client" : "127.0.0.1",
    "allUsers" : [],
    "user" : ""
}



 Comments   
Comment by Robert Stam [ 05/Feb/16 ]

When run against server version 3.0.8 the captured profile information is a little bit different because server version 3.0.8 did not yet have the find command. In this case the limit of 2 manifests itself as { ntoreturn : 2 }:

> db.system.profile.find().pretty()
{
        "op" : "query",
        "ns" : "test.test",
        "query" : {
                "Name" : "Tom"
        },
        "cursorid" : 32189135666,
        "ntoreturn" : 2,
        "ntoskip" : 0,
        "nscanned" : 0,
        "nscannedObjects" : 2,
        "keyUpdates" : 0,
        "writeConflicts" : 0,
        "numYield" : 0,
        "locks" : {
                "Global" : {
                        "acquireCount" : {
                                "r" : NumberLong(2)
                        }
                },
                "MMAPV1Journal" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Database" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Collection" : {
                        "acquireCount" : {
                                "R" : NumberLong(1)
                        }
                }
        },
        "nreturned" : 2,
        "responseLength" : 76,
        "millis" : 3,
        "execStats" : {
                "stage" : "COLLSCAN",
                "filter" : {
                        "Name" : {
                                "$eq" : "Tom"
                        }
                },
                "nReturned" : 2,
                "executionTimeMillisEstimate" : 0,
                "works" : 3,
                "advanced" : 2,
                "needTime" : 1,
                "needFetch" : 0,
                "saveState" : 0,
                "restoreState" : 0,
                "isEOF" : 0,
                "invalidates" : 0,
                "direction" : "forward",
                "docsExamined" : 2
        },
        "ts" : ISODate("2016-02-05T00:00:44.821Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
{
        "op" : "killcursors",
        "ns" : "",
        "keyUpdates" : 0,
        "writeConflicts" : 0,
        "numYield" : 0,
        "locks" : {
                "Global" : {
                        "acquireCount" : {
                                "r" : NumberLong(2)
                        }
                },
                "MMAPV1Journal" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Database" : {
                        "acquireCount" : {
                                "r" : NumberLong(1)
                        }
                },
                "Collection" : {
                        "acquireCount" : {
                                "R" : NumberLong(1)
                        }
                }
        },
        "millis" : 0,
        "execStats" : {
 
        },
        "ts" : ISODate("2016-02-05T00:00:44.843Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
>

Comment by Robert Stam [ 04/Feb/16 ]

I also turned on profiling while running the above test. See the { limit : 2 } in the captured query below:

> db.system.profile.find().pretty()
{
        "op" : "query",
        "ns" : "test.test",
        "query" : {
                "find" : "test",
                "filter" : {
                        "Name" : "Tom"
                },
                "limit" : 2
        },
        "keysExamined" : 0,
        "docsExamined" : 2,
        "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" : 2,
        "responseLength" : 177,
        "protocol" : "op_query",
        "millis" : 0,
        "execStats" : {
                "stage" : "LIMIT",
                "nReturned" : 2,
                "executionTimeMillisEstimate" : 0,
                "works" : 4,
                "advanced" : 2,
                "needTime" : 1,
                "needYield" : 0,
                "saveState" : 0,
                "restoreState" : 0,
                "isEOF" : 1,
                "invalidates" : 0,
                "limitAmount" : 2,
                "inputStage" : {
                        "stage" : "COLLSCAN",
                        "filter" : {
                                "Name" : {
                                        "$eq" : "Tom"
                                }
                        },
                        "nReturned" : 2,
                        "executionTimeMillisEstimate" : 0,
                        "works" : 3,
                        "advanced" : 2,
                        "needTime" : 1,
                        "needYield" : 0,
                        "saveState" : 0,
                        "restoreState" : 0,
                        "isEOF" : 0,
                        "invalidates" : 0,
                        "direction" : "forward",
                        "docsExamined" : 2
                }
        },
        "ts" : ISODate("2016-02-04T23:55:31.901Z"),
        "client" : "127.0.0.1",
        "allUsers" : [ ],
        "user" : ""
}
>

Comment by Robert Stam [ 04/Feb/16 ]

I am unable to reproduce this. I used the following code:

public static class Program
{
    public class C
    {
        public int Id { get; set; }
        public string Name { get; set; }
    }
 
    public static void Main(string[] args)
    {
        var client = new MongoClient("mongodb://localhost");
        var database = client.GetDatabase("test");
        var collection = database.GetCollection<C>("test");
 
        database.DropCollection("test");
        collection.InsertMany(new[]
        {
            new C { Id = 1, Name = "Tom" },
            new C { Id = 2, Name = "Tom" },
            new C { Id = 3, Name = "Tom" },
        });
 
        var filter = Builders<C>.Filter.Eq(c => c.Name, "Tom");
        var documents = collection.Find(filter).Limit(2).ToList();
        Console.WriteLine($"{documents.Count} documents were returned");
    }
}

And the output was:

2 documents were returned

Which is evidence that the limit is honored.

Comment by bothead [ 15/Oct/15 ]

Tests with old and new driver queries.

Comment by bothead [ 15/Oct/15 ]

I ran another test using the bare bones driver for both 1.10.0 and 2.1.0, and the old driver is much faster. The query with the old driver takes about ~215ms each time I run it, whereas the query with the new driver takes about ~350ms each time I run it. This is a pretty big difference in performance. I have attached the same code.

Comment by bothead [ 15/Oct/15 ]

I added the ToString call as follows:

                var filter = Builders<Tenant>.Filter.Eq(e => e.Name, name);
                var find = this.Collection.Find(filter).Limit(1);
 
                var test = find.ToString();
                Trace.Write(test);

Here is the output:

                "find({ \"Name\" : \"dev\" }).limit(1)"

So... the output shows the limit, however the profiler does not.

Comment by bothead [ 14/Oct/15 ]

The profiler logs I included in the bug report were the result of setting db.setProfilingLevel(2). I also suspected this may not be our issue, as you said would like to rule it out. I will try call to String and report that as well.

Comment by Craig Wilson [ 14/Oct/15 ]

I don't believe that would be the problem. However, just to ensure this isn't it, could you include the generated queries for both? You can do this by enabling the profiler on the server and getting all the queries that way. In the shell, you'd use db.setProfilingLevel(2). After you have both queries, turn that back to it's previous setting.

Also, you can use .ToString() in 2.0.1 to get the shell syntax of the query we'll generate.

Generated at Wed Feb 07 21:39:37 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.