MongoDB causing large delay with unknown findOne method - New Relic

Question

I setup newrelic to better understand what bottlenecks my app has and I found an issue that I can't seem to figure out.

Majority of my delays are being caused by mongoDB user.fineOne but main issue is that I can't seem to find the where in the code is it happening.

In the image below you can see the trace details for a call to get/all/proposal end point of my API. It first 14 method calls which are the middleware's in my server.js and after that its a Middleware: Authenticate within which it has MongoDB Users findOne and thats where the delay is.

Code for get/all/proposals:

app.get('/all/proposals',isLoggedIn,function(req, res) {
   Proposal.find().sort({proposalNo: -1}).limit(5).exec(function(err,proposal){
       if(err){
           console.log(err);
       }else{
           console.log("All Proposals " + proposal);
           res.json(proposal);
       }
   });
});

Now at no point that I can see am I running a User.findOne call on MongoDB at get/all/proposals. Initially I thought it was the isLoggedIn middleware where I check if the user is in session (Passport.js) but as you can see isLoggedIn Middleware only takes 0.0222(ms).

The same issue appears on multiple API endpoints i.e get/caseStudy and its always the user.findOne another example below:

Can anyone help me resolve this. Please let me know if you need more detail which Im guessing you will.

Update: Server.js Code

 // set up ======================================================================

require('newrelic');
var express  = require('express');
var app      = express();                               // create our app w/ express
var server = require('http').createServer(app);
var mongoose = require('mongoose');                     // mongoose for mongodb
var port     = process.env.PORT || 8080;                // set the port
var database = require('./config/db');                  // load the database config
var morgan = require('morgan');                         // log requests to the console (express4)
var bodyParser = require('body-parser');                // pull information from HTML POST (express4)
var methodOverride = require('method-override');        // simulate DELETE and PUT (express4)
var passport = require('passport');
var flash    = require('connect-flash');
var session      = require('express-session');
var cookieParser = require('cookie-parser');
var compression = require('compression');
var nodemailer = require('nodemailer');
var busboy = require("connect-busboy");

// configuration ===============================================================


mongoose.connect(database.url);                                 // connect to mongoDB database on modulus.io
require('./config/passport')(passport);
app.use(express.static(__dirname + '/public'));  
app.use(express.static(__dirname + '/views'));  // set the static files location /public/img will be /img for users
app.use(busboy());
app.use(compression()); //use compression
app.use(morgan('dev'));                                         // log every request to the console
app.use(bodyParser.urlencoded({'extended': true}));             // parse application/x-www-form-urlencoded
app.use(bodyParser.json());                                     // parse application/json
app.use(bodyParser.json({ type: 'application/vnd.api+json' })); // parse application/vnd.api+json as json
app.use(methodOverride());
app.use(cookieParser());                                        // read cookies (needed for auth)
app.set('view engine', 'ejs');                                  // set up ejs for templating

// required for passport
app.use(session({ secret: '',  resave: false, saveUninitialized: false })); // session secret
app.use(passport.initialize());
app.use(passport.session());                                    // persistent login sessions
app.use(flash());                                               // use connect-flash for flash messages stored in session

 // routes ======================================================================

require('./routes/index.js')(app, passport); // load our routes and pass in our app and fully configured passport
//require('./routes/knowledgeBase/index.js')(app, passport);
require('./routes/bios/index.js')(app, passport);

 // listen (start app with node server.js) ======================================

app.listen(port);
console.log("App listening on port " + port);

Update 2: Passport.js

// config/passport.js

// load all the things we need
var LocalStrategy   = require('passport-local').Strategy;
var crypto = require("crypto");
var api_key = '';
var domain = '';
var mailgun = require('mailgun-js')({apiKey: api_key, domain: domain});
// load up the user model
var User            = require('../app/models/user');

 // expose this function to our app using module.exports
 module.exports = function(passport) {

// =========================================================================
// passport session setup ==================================================
// =========================================================================
// required for persistent login sessions
// passport needs ability to serialize and unserialize users out of session

// used to serialize the user for the session
passport.serializeUser(function(user, done) {
    done(null, user.id);
});

// used to deserialize the user
passport.deserializeUser(function(id, done) {
    User.findById(id, function(err, user) {
        done(err, user);
    });
});

// =========================================================================
// LOCAL SIGNUP ============================================================
// =========================================================================
// we are using named strategies since we have one for login and one for signup
// by default, if there was no name, it would just be called 'local'

passport.use('local-signup', new LocalStrategy({
        // by default, local strategy uses username and password, we will override with email
        firstNameField: 'firstName',
        lastNameField: 'lastName',
        usernameField: 'email',
        passwordField: 'password',
        jobTitleField: 'jobTitle',
        startDateField: 'startDate',
        passReqToCallback: true // allows us to pass back the entire request to the callback
    },

    function(req, email, password, done) {

        // find a user whose email is the same as the forms email
        // we are checking to see if the user trying to login already exists
        User.findOne({
            'email': email
        }, function(err, user) {
            // if there are any errors, return the error
            if (err)
                return done(err);

            // check to see if theres already a user with that email
            if (user) {
                return done(null, false, {
                    message: 'That email is already taken.'
                });
            }
            else {

                var token = crypto.randomBytes().toString();
                // if there is no user with that email
                // create the user
                var newUser = new User();

                // set the user's local credentials
                newUser.firstName = req.body.firstName;
                newUser.lastName = req.body.lastName;
                newUser.email = email;
                newUser.password = newUser.generateHash(password); // use the generateHash function in our user model
                newUser.jobTitle = req.body.jobTitle;
                newUser.startDate = req.body.startDate;
                newUser.birthday = req.body.birthday;
                newUser.region = req.body.region;
                newUser.sector = req.body.sector;
                newUser.accountConfirmationToken = token;
                newUser.accountConfirmationTokenExpires = Date.now() + 3600000;
                newUser.accountVerified = 'false';



                // save the user
                newUser.save(function(err) {
                    if (err)
                        throw err;
                    else {
                        return done(null, newUser);
                    }
                });
            }

        });

    }));

// =========================================================================
// LOCAL LOGIN =============================================================
// =========================================================================
// we are using named strategies since we have one for login and one for signup
// by default, if there was no name, it would just be called 'local'

passport.use('local-login', new LocalStrategy({
    // by default, local strategy uses username and password, we will override with email
    usernameField : 'email',
    passwordField : 'password',
    passReqToCallback : true // allows us to pass back the entire request to the callback
},
function(req, email, password, done) { // callback with email and password from our form

    // find a user whose email is the same as the forms email
    // we are checking to see if the user trying to login already exists
    User.findOne({ 'email' :  email }, function(err, user) {
        // if there are any errors, return the error before anything else
        if (err)
            return done(err);

        // if no user is found, return the message
        if (!user)
            return done(null, false, req.flash('loginMessage', 'No user found.')); // req.flash is the way to set flashdata using connect-flash

        // if the user is found but the password is wrong
        if (!user.validPassword(password))
            return done(null, false, req.flash('loginMessage', 'Oops! Wrong password.')); // create the loginMessage and save it to session as flashdata

        if(user.accountVerified == 'false')    
            return done(null, false, req.flash('loginMessage', 'Looks like you have not verified your account after registeration.'));
        else
            user.lastLogin = Date.now();
            user.save(function(err) {
                if (err)
                    throw err;
                else {
        // all is well, return successful user
                    return done(null, user);
                }
            });
    });

}));

};

Update 3: isLoggedIn function

 // route middleware to make sure a user is logged in
  function isLoggedIn(req, res, next) {

// if user is authenticated in the session, carry on 
if (req.isAuthenticated())
    return next();

    // if they aren't redirect them to the home page
    res.redirect('/');
 }

update 4: Steps for getting proposals

Step 1: First load the proposals page

 app.get('/proposals',isLoggedIn,function(req, res) {
    res.render('proposals.ejs', {
        user : req.user // get the user out of session and pass to template
    });
});

Step 2: The proposals page has a angular.js controller/factory which calls the following function on page-load to get data.

// =========================================================================
// FUNCTIONS TO BE RUN WHEN THE PAGE FIRST LOADS TO POPULATE FRONT-END =====
// =========================================================================
$scope.intialize = function() {
    $scope.getAllSectors();
    $scope.getLatestProposals();
}

// ===============================
// GET LATEST *5* PROPOSALS  =====
// ===============================
factory.getLatestProposals = function() {

    return $http.get('/all/proposals')
        .then(function(response) {
            //promise is fulfilled
            deferred.resolve(response.data);

            console.log("readched the filtered project service!");

            //promise is returned
            // return deferred.promise;
            return response.data;

        }, function(response) {
            deferred.reject(response);

            //promise is returned
            return deferred.promise;
        });
};

Step 3: The /all/proposals route is called

 // =======================
//  GET All Proposals =====
//  =======================
app.get('/all/proposals',isLoggedIn,function(req, res) {
   Proposal.find().sort({proposalNo: -1}).limit(5).exec(function(err,proposal){
       if(err){
           console.log(err);
       }else{
           console.log("All Proposals " + proposal);
           res.json(proposal);
       }
   });
});

Answer 1

After looking at the code that you provided, it appears that the .findOne() that appears in your performance log is the one performed when searching for a user and authenticating him.

Thus, it appears that the performance bottleneck is occurring in one of the below 2 queries:

/*
 * LOCAL LOGIN
 */
// find a user whose email is the same as the forms email
    // we are checking to see if the user trying to login already exists
    User.findOne({ 'email' :  email }, function(err, user) {
...


/*
 * LOCAL SIGNUP
 */
    // find a user whose email is the same as the forms email
    // we are checking to see if the user trying to login already exists
    User.findOne({
        'email': email
...

I see that in both of your passport local strategies you are searching against the email field, thus you can improve performance by creating an index on that field.

To try optimizing the LOCAL LOGIN findOne query even more, you can try adding an index for the users collection on the email field, if you haven't already:

// This index will optimize queries that search against the {email} field
db.users.createIndex({ email: 1});

UPDATE #1

I found a related Stack Overflow topic that might be the answer to your performance issue - you should update the below line in your express.js configuration:

app.use(session({ secret: '',  resave: false, saveUninitialized: false }));

to

app.use(session({ secret: '',  resave: true, saveUninitialized: true }));

I also managed to find these notes regarding the resave and saveUninitalized properties in the Express JS documentation:

saveUninitialized

Forces a session that is "uninitialized" to be saved to the store. A session is uninitialized when it is new but not modified. Choosing false is useful for implementing login sessions, reducing server storage usage, or complying with laws that require permission before setting a cookie. Choosing false will also help with race conditions where a client makes multiple parallel requests without a session.

The default value is true, but using the default has been deprecated, as the default will change in the future. Please research into this setting and choose what is appropriate to your use-case.

Note if you are using Session in conjunction with PassportJS, Passport will add an empty Passport object to the session for use after a user is authenticated, which will be treated as a modification to the session, causing it to be saved. This has been fixed in PassportJS 0.3.0

resave

Forces the session to be saved back to the session store, even if the session was never modified during the request. Depending on your store this may be necessary, but it can also create race conditions where a client makes two parallel requests to your server and changes made to the session in one request may get overwritten when the other request ends, even if it made no changes (this behavior also depends on what store you're using).

The default value is true, but using the default has been deprecated, as the default will change in the future. Please research into this setting and choose what is appropriate to your use-case. Typically, you'll want false.

How do I know if this is necessary for my store? The best way to know is to check with your store if it implements the touch method. If it does, then you can safely set resave: false. If it does not implement the touch method and your store sets an expiration date on stored sessions, then you likely need resave: true.