Slow responses from MongoDb with C#

Question

I have recently been working to set up a Mongo db server to act as an object cache for a website. However after setting everything up I am concerned that the performance is quite slow.

It is a single server, not part of a replica set or sharded. I am running all tests from my local machine to the server which is on a Windows Azure VM.

For example I have a collection of approximate 5,500 documents where each document stores a link to an external site. A typical document looks like this:

{ 
    "_id" : 5001 , 
    "Active" : true , 
    "CategoryId" : 1 , 
    "Crci" : "V" , 
    "CultureId" :  null,
    "DateUpdated" : { "$date" : 1333370987810} ,
    "Description" : "National Careers Service: Childminder" ,
    "Keywords" :  null ,
    "MaxLevel" :  null ,
    "MinLevel" :  null ,
    "PhoneNumber" :  null ,
    "Priority" : 1 , 
    "Title" : "National Careers Service: Childminder" ,
    "WebUrl" : "https://nationalcareersservice.direct.gov.uk/advice/planning/jobprofiles/Pages/childminder.aspx"
}

I tried the following sample query from my code using the official 10gen driver and it took an average of 2.7-3.0 seconds to complete:

var query = (from er in lib.All()
             where er.Id > 7000
             select er);

(lib is a thin wrapper class and All() exposes the IQuerable interface)

the query above returns approximately 3000 records.

I have checked the query being generated by the linq and it seems to be fine:

{_id: { $gt: 7000} }

running the same query from umongo (a GUI interface) returns the results in less than a second which is more what I expected.

The fields are indexed properly using ensure index (called the once when the collection is populated, after that this is read-only data:

collection.EnsureIndex(new IndexKeysBuilder<ExternalResourceView>().Ascending(er => er.Id), IndexOptions.SetUnique(true));
collection.EnsureIndex(new IndexKeysBuilder<ExternalResourceView>().Ascending(er => er.CategoryId));
collection.EnsureIndex(new IndexKeysBuilder<ExternalResourceView>().Ascending(er => er.Active));
collection.EnsureIndex(new IndexKeysBuilder<ExternalResourceView>().Ascending(er => er.Keywords));

The index seem to be used for the search:

db.ExternalResources.find({_id: {$gt: 7000}}).explain()

{
        "cursor" : "BtreeCursor _id_",
        "isMultiKey" : false,
        "n" : 3087,
        "nscannedObjects" : 3087,
        "nscanned" : 3087,
        "nscannedObjectsAllPlans" : 3087,
        "nscannedAllPlans" : 3087,
        "scanAndOrder" : false,
        "indexOnly" : false,
        "nYields" : 0,
        "nChunkSkips" : 0,
        "millis" : 5,
        "indexBounds" : {
                "_id" : [
                        [
                                7000,
                                1.7976931348623157e+308
                        ]
                ]
        },
        "server" : <Server Name>
}

Even single direct id lookups take nearly 100 milliseconds to return in the code, eg:

 from er in lib.All()
 where er.Id == 3100
 select er

Is there any setup I am missing that would speed up my searches or were my expectations unrealistic to start with?

Edit: I have tried completely rebuilding / repopulating the database but it still feels unacceptably slow

Edit 2: I am enclosing the wrapper class in its entirety. I don't think it is at fault, but just in case:

public abstract class MongoLibrary<TViewModel> : ILibrary<TViewModel> where TViewModel : class
{
    private readonly MongoCollection _collection;
    private readonly string _dbName;
    private readonly string _collectionName;
    private readonly string _connString;

    protected MongoLibrary(string connString, string dbName, string collectionName)
    {
        _connString = connString;
        connString += "/" + dbName;
        var client = new MongoClient(connString);
        _dbName = dbName;
        _collectionName = collectionName;
        var db = client.GetServer().GetDatabase(dbName);
        _collection = db.GetCollection<TViewModel>(collectionName);
    }

    public abstract void ConfigureIndex(MongoCollection collection);

    public IQueryable<TViewModel> All()
    {
        return _collection.AsQueryable<TViewModel>();
    }

    public IEnumerable<TViewModel> GetWhere(Func<TViewModel, bool> predicate)
    {
        return _collection.AsQueryable<TViewModel>().Where(predicate);
    }

    protected void PopulateData(IEnumerable<TViewModel> views, int instanceToUpdate)
    {
        var ports = //port numbers hidden for security

        foreach (var port in ports)
        {
            var client = new MongoClient(string.Format("{0}:{1}/{2}", _connString, port, _dbName));

            var db = client.GetServer().GetDatabase(_dbName);
            var coll = db.GetCollection(_collectionName);
            coll.Drop();
            coll.InsertBatch(views);
        }
        ConfigureIndex(_collection);
    }

}

Edit 3: Server logs profiling a query to the database:

The query was just an artificial query to demonstrate performance. The query was:

        var sw = new Stopwatch();
        sw.Start();
        var temp = _externalResourceLibrary.All().Where(er => er.Id > 7500).ToList();
        sw.Stop();

You can see from the logs it authenticated then retrieved the data in 2 trips. in total there 2677 documents retrieved. Time taken was 3580 ms (averaged over 5 runs)

>db.system.profile.find().limit(10).sort( { ts : -1 } ).pretty()  
{
    "op" : "getmore",
    "ns" : "cache.ExternalResources",
    "query" : {
        "_id" : {
            "$gt" : 7500
        }
    },
    "cursorid" : NumberLong("949848842778037962"),
    "ntoreturn" : 0,
    "keyUpdates" : 0,
    "numYield" : 0,
    "lockStats" : {
        "timeLockedMicros" : {
            "r" : NumberLong(9486),
            "w" : NumberLong(0)
        },
        "timeAcquiringMicros" : {
            "r" : NumberLong(4),
            "w" : NumberLong(5)
        }
    },
    "nreturned" : 2576,
    "responseLength" : 1511874,
    "millis" : 9,
    "ts" : ISODate("2014-01-28T10:52:16.125Z"),
    "client" : <ipAddress>,
    "allUsers" : [
                    {
                        "user" : <username>,
                        "userSource" : <dbName>;
                    }
    ],
    "user" : <username>@<dbName>;
}
{
    "op" : "query",
    "ns" : "cache.ExternalResources",
    "query" : {
            "_id" : {
                    "$gt" : 7500
            }
    },
    "cursorid" : NumberLong("949848842778037962"),
    "ntoreturn" : 0,
    "ntoskip" : 0,
    "nscanned" : 102,
    "keyUpdates" : 0,
    "numYield" : 0,
    "lockStats" : {
            "timeLockedMicros" : {
                    "r" : NumberLong(749),
                    "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                    "r" : NumberLong(5),
                    "w" : NumberLong(3)
            }
    },
    "nreturned" : 101,
    "responseLength" : 64013,
    "millis" : 0,
    "ts" : ISODate("2014-01-28T10:52:15.954Z"),
    "client" : <ipAddress>,
    "allUsers" : [
            {
                    "user" : <username>,
                    "userSource" : <dbName>;
            }
    ],
    "user" : <username>@<dbName>;
}
{
    "op" : "command",
    "ns" : "cache.$cmd",
    "command" : {
            "authenticate" : 1,
            "user" : <username>,
            "nonce" : <nonce>;,
            "key" : <key>;
    },
    "ntoreturn" : 1,
    "keyUpdates" : 0,
    "numYield" : 0,
    "lockStats" : {
            "timeLockedMicros" : {
                    "r" : NumberLong(381),
                    "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                    "r" : NumberLong(9),
                    "w" : NumberLong(3)
            }
    },
    "responseLength" : 79,
    "millis" : 0,
    "ts" : ISODate("2014-01-28T10:52:15.938Z"),
    "client" : <ipAddress>,
    "allUsers" : [
            {
                    "user" : <username>,
                    "userSource" : <dbName>
            }
    ],
    "user" : <username>@<dbName>;
}

Answer 1

Issues were caused by network latency