shtylman.com

node.js error logging

2013-03-16T00:00:00+00:00

One of the first things you should do for any application you plan to deploy is make sure you have proper error logging in place. You should know when things are failing and should be able to act on failure information.

Lets start with a basic node application that might have an error

inflexible error logging

function will_error(cb) {
    return cb(new Error('foobar'));
}

will_error(function(err) {
    if (err) {
        return console.log(err);
    }
});

It is clear that when we call will_error, our app will get back an error that we should handle. By just using console.log as we have done, we are losing valuable error information.

Not only are we losing error information to help in debugging, but we are also not doing anything to alert ourselves to potential problems our app is having. The first step to better error information is to introduce a basic logging library.

basic logging layer

One step in the right direction is to use a simple logging library like book. Book will become the point of capture for our log entries allowing us to make use of them in a more flexible manner.

var log = require('book');

function will_error(cb) {
    return cb(new Error('foobar'));
}

will_error(function(err) {
    if (err) {
        return log.error(err);
    }
});

Now, instead of logging to console, we are logging through book which provides a few log events and also logs to console for us. The application is identical to what we had before, except now we can leverage our logging library to get more information from our errors.

introduce an alerting solution

Lets say we want to leverage an alerting service like sentry to know when things are breaking. We can easily do this when we use a simple logging layer.

The bookrc module allows us to educate our book logging layer without affecting application code.

Simply alter the require('book') line to require('bookrc') and put the following file in the root of your project.

Now when we run our application and an error happens, we will be alerted via the sentry web interface.

This provides us with a lot more information about the specific error.

error level
stacktrace with relevant code blocks
location of logging statement
git commit id
loaded modules

All of this information is valuable when tracking down errors in deployed applications and we got it all for free without having to change our application code!

how it works

The bookrc module simply looks for a bookrc.js file and loads that as itself. What we put into this bookrc.js file is completely up to us. I could have easily added logging to a file, additional alerting or other filters to the book logger we created. Book logging is very flexible and can easily be extended with many different plugins.

Now go and purge those useless console.logs!

cron SHELL power

2013-03-08T00:00:00+00:00

If you don't know what cron is this post is not for you.

Using the SHELL variable in cron is more powerful than you may realize.

typical crontab

Most people will have this type of setup in their crontab.

NODE_ENV=production
OTHER_VAR=foo

*/10 * * * * /path/to/node /path/to/my/script.js

If you don't want to repeat /path/to/node (or your runtime) over and over, you will add a PATH variable to go with the other variables.

But what happens if you want to use something like nvm or rvm or virtualenv, etc? It is not uncommon to have the above change to something like the following

*/10 * * * * /path/to/my/launcher.sh
*/10 * * * * /path/to/my/launcher_another.sh

Now you have several shell scripts which invoke the required commands to setup the environment and then run whatever program.

enter SHELL

There is a little known special env variable for cron: SHELL. Most people know this variable can be used to change the shell your scripts run run (i.e. SHELL=/bin/bash), but it can actually run any file!

So lets say I use nvm and want to setup my environment. Instead of making custom launchers for each command, I can simply do the following:

SHELL=/path/to/setup/cron.bash

*/10 * * * * node $HOME/foo.js

Now lets look at what cron.bash might look like

For the most part it looks just like any other shell script. The important magical parts are the last 4 lines. These lines put back the SHELL variable to /bin/bash and then execute a bash shell to run the cronline command (the stuff for the specific cronjob).

Now our cron files have a consistent environment setup and we can simply run whatever commands we need without further PATH tricks or nonsense.

Go forth and update your dirty crontabs!

expressjs re-routing

2013-01-07T00:00:00+00:00

One of the most common questions I get asked when I talk about express is how I manage my routes. While I generally point out things like app.param() and other middleware tricks, I am left just saying that I don't have a great solution. Well, I am happy to say that as of express 3.0.6 I have a better answer; use the router!

Routes, why do I care?

Maybe you don't like routers, but they do serve a purpose. If you are writing a web app or even a headless api, you can benefit from the simple separation and organization a nice router will provide. Just think of it as a URL if statement on steroids!

The typical express application looks something like this:

var app = express();

/// top level routes

app.get('/', function(req, res, next) { ... } );

/// blog post routes

app.get('/post/:post_id', function(req, res, next) { ... });
app.post('/post/:post_id/comment', function(req, res, next) { ... });
app.del('/post/:post_id/comment', function(req, res, next) { ... });

/// etc

As the number of routes you want your app to handle grows, you might find that this single file approach gets out of control (justifiably so) and move to a multi-file approach where you export handler functions.

var post = require('./routes/post');
app.get('/post/:post_id', post.get);
app.post('/post/:post_id/comment', post.addComment);
app.del('/post/:post_id/comment', post.removeComment);

The problem is that your routes/post file is now void of the actual route information. This can make it a bit more challenging to see what is going on and debug.

Router to the rescue!

Instead of exporting individual functions from your routes files. You can now use the express router without creating a whole new express app.

Imagine we have the following routes.js file

var express = require('express');
var router = new express.Router();

// we can use all of the HTTP verbs on the router
router.get('/bar', function(req, res, next) { ... });
router.post('/baz', function(req, res, next) { ... });

// at the end we export this router as a single unit
module.exports = router;

And in app.js

var app = express();

// this is for the routes in this file
app.use(app.router);

// this creates /foo/bar and /foo/baz
// /foo could be any prefix
app.use('/foo', require('./routes').middleware);

// our typical app routes can still go here
app.get('/', function(req, res, next) { ... });

What we have done is left the relevant path information in the routes.js file and "mounted" those routes under the /foo url. Now we have basic routes and handlers defined separately from where the parent application may be mounting them.

Note: You could app.use(require('./routes').middleware); if you wanted to host the routes from the site root.

Complete app example

I have created a gist which you can clone or review below as a more complete example.

app.js

Our main app.js (server.js, index.js, whatever.js) file does not change much. The only major difference is that instead of using app.get for our /user and /post routes in the file, we use app.use and inject them under their respective parent urls.

routes/user.js

We now put all of the routes we want to contain as one unit in this file. Notice that this file does not know that it will be served under /user. It could be served from any route by a parent file. Using this approach you could reuse sets of routes in multiple places (not suggesting this is what you want :)

routes/post.js

Like the app, the router has a .param() function which allows you to consolidate parameter handling. In this example, we see that since all of these routes will need a post, we use the :post_id parameter from the url to make sure a post is loaded before any route is run.

Now go forth and bring order to those routes! Remember that you will need express version 3.0.6.

npm - git with the program

2012-12-26T00:00:00+00:00

npm is a simple package manager for javascript projects. All it takes to use npm for your project is a simple file called package.json. This file contains some basic metadata about your project (similar to setup.py for pip, gemspec for ruby, etc).

Example package.json file

{
    "name": "awesome-package-name",
    "version": "0.0.0",
    "description": "the answer to life and the universe",
    "main": "./entry-file.js"
}

Thats all you need for a basic description of your project. If you have a public project and are hosting it publicly, I also suggest adding a repository field so others can find your code.

{
    "repository": {
        "type": "git",
        "url": "git://github.com/shtylman/awesome-package-name.git"
    }
}

For versioning, I suggest you take a quick look at semver

dependencies

Now, if your module is awesome (and there is no reason for it not to be), then you will most likely use other modules. Fortunately, this is really easy and all you need to add is a dependencies field.

{
    "dependencies": {
        "mime": "1.2.7",
        "yummy": "1.0.1"
    }
}

I recommend using exact versions so when you revisit your code months later, you can easily identify what versions you had installed and the module worked with.

Now you can just run npm install and npm will fetch the exact versions of the dependencies specified.

If you want to add more dependencies later, just edit the file. npm ls can show you what you have installed but not added (extraneous).

where does git fit in?

The above dependency specification should look very familiar to anyone currently writing javascript modules and publishing them to npm. What many don't realize is that you can also specify git repositories!

{
    "dependencies": {
        "dom": "git://github.com/shtylman/dom.git"
    }
}

Now when you npm install, npm will fetch the latest version of the master branch from the git repo you specified!

If you want a specific tag or commit just specify a # followed by the tag or commit id.

{
    "dependencies": {
        "dom": "git://github.com/shtylman/dom.git#v0.0.1"
    }
}

When specifying a commit sha1, you don't have to specify the whole sha. I have found that using just the first 6 characters is good enough as it will most likely be unique in your repo.

{
    "dependencies": {
        "dom": "git://github.com/shtylman/dom.git#449852"
    }
}

but wait! there's more!

As of node v0.8.14, you can make your github urls even shorter!

{
    "dependencies": {
        "dom": "shtylman/dom#v0.0.1"
    }
}

Note that just like the long form url, you can specify a #commit. So if you can't publish to npm, or have some other naming issue, you can easily reference code which lives on github.

Keep in mind that the shortform syntax does not work on npm < 1.1.64. So if you have an older version of node, you will need to make sure your npm is up to date with *npm install -g npm***

use cases and wrap-up

works with users or organizations! the format is simply owner/repo#commit
private repos work great with the git approach so long as the proper ssh keys are setup in github
you don't have to npm publish to use a module
if your module name is already taken and you are not creative enough to make a new one

the copy & paste virus

2012-12-13T00:00:00+00:00

If there is bad code, I will find it, and I will copy it.

Years ago (long before the web 2.0 days) I wrote JavaScript. Then I stopped. These days, I again write a lot of JavaScript. Other people also write a lot of JavaScript and not a single day goes by that someone doesn't write some new jQuery plugin or other interesting JavaScript client library. This is fantastic! All of these developers are solving their problems and sharing the solution with everyone else.

However, when I look back on the JavaScript that I would see someone write years ago and the JavaScript I see being distributed today, I don't see much difference. Sure, some styles and html technologies are better, but I still see everyone delivering JavaScript which all looks like a variation of the following.

(function(window) { // or $ depending if it is a jQuery plugin
    var run,
        out,
        find,
        coconut,
        tricycle,
        bus,
        ... 500 other variables ...
        potato,
        tomato,
        yarn,
        dog,
        flag,
        hippo,
        pencil,
        pen;

    function something() {
    };

    ... hundreds of lines of some functions, classes, who knows what all referencing itself

    global.foo = {
        something: function() {
        },
        another: function() {
        },
    }
})(window); // or jQuery again depending

That's it. One giant file full of code that self references, nests over and over and is contained within a closure just for fun! Why are we doing this? Do we (as developers) hate clarity? Do we enjoy writing a giant closure to do nothing?

Think about how you write code and libraries in other languages. How often do you dump everything into a "mega" file. How often to do put all of it inside one single outer function just cause? NEVER, that is how often. In other languages you use import, require, include, etc.. so why do we continue to allow our JavaScript to look like unmaintainable shit? No module system.

WRONG! There is NO reason. JavaScript has a super simple module system and countless people are overlooking it! I am talking about the commonjs require system. Here is all you need to know about commonjs requires: They work, they require no language extensions, and they CAN do what you need. That's it. Everything else is a tooling and education problem. Period.

commonjs intermission

Since not everyone is familiar with commonjs, let me do a super quick primer with the basics.

every file is a module
everything in a file is private to the file unless explicitly exported
any valid JavaScript type can be exported through module.exports
the require function is used to load a module

That's it! Now all you have to do is move some of that code into a separate file and require it from your main file. Lets say I am writing a basic client library to do some stuff.

// main file for our new client side lib
var parser = require('./parser');
var tree = require('./tree');

// we don't export this, so it is private to the file
var private = 'foo';

// modules can also just export a function
module.exports = function() {
};

Now we create a parser.js and tree.js files alongside out main entry file

// parser.js
module.exports.parse = function(str) {
};

// tree.js
var Tree = function() {
};

...

module.exports = Tree;

I have kept the above examples brief specifically to show the super simple nature of the commonjs module system. No complex dependency maps, no global closures, no spaghetti.

all nails and no hammer

So those of you who are still reading are certainly wondering how you are going to take the above code and make it work in a browser. No browser supports the "require" syntax and in the end you wanted to have one file in your script tag. Well, I guess that's that, end of that fun experiment. NO. Stop thinking about it as if you don't have a computer in front of you. As a developer, one of the best improvements to productivity can be gained from your tools. The same is true in the above examples. Instead of manually putting your code in a giant closure, wondering what syntax you need for AMD loaders, and what to close over, LET THE TOOL DO THE WORK

I am going to say that one more time, since I don't think enough people appreciate this.

LET THE TOOL DO THE WORK

the hammer

Today is the day you say NO MORE to massive, unorganized repositories of JavaScript files and start using modules. You don't have to add any extra metapackages or publish your code in any special place to do this. To get you started, I have provided a very very basic tool which will build your multi file JavaScript projects called reunion. I have even provided a makefile snippet to use it when creating the final code bundle for others.

use reunion in your codebase NOW with minimal effort on your part!

You don't have to dive in 100% from day 1. If you have a jQuery plugin, you can still use that wonderful global $ var $ = window.jQuery in your module works!. However, these first steps will make your code that much easier to follow and eventually you will be able to require('jQuery'); just like anything else!

no overhead

Reunion require functionality is TINY. The minified require function comes in at ~140 bytes! Since reunion puts everything into a single closure for you, you still benefit from excellent minification. Even more, each module is put into a function which means it can be minified locally and allows for the minifier to reuse more of the shorter variable names.

It wasn't until I started writing node.js code and modules that I realized how stupid front end file organization and usage was and cotninues to be for so many people. As soon as I started writing modules and separating code, JavaScript got that much easier and maintainable. Tests are easier to localize and common components can be shared much easier. More importantly, given the right tool, I could package any module however I wanted!

What about other loaders? We are back to a tooling issue. The great thing about commonjs requires is that they are super easy to tool around! If you want AMD output, just send me a pull request for and AMD target. That's it! Now only one place has to worry about the right closure format. Everyone else just has simple and clean JavaScript!

the future

Reunion is a very simple tool. In the next post, I am going to talk about tools like npm, script, and browserify and how they can completely revolutionize how you develop and share JavaScript.

And remember! LET THE TOOL DO THE WORK!

fraud is not a merchant problem

2012-04-27T00:00:00+00:00

I recently had the distinct pleasure of being hit with some chargebacks through my USD payment processor Dwolla. After talking to their head of fraud detection and prevention it became clear they they did not understand their own business.

One of the choice phrases that kept being repeated was that fraud was a risk and a part of doing business for the merchant (me). I argue that it is not a part of doing business for the merchant if they are using a service such as Dwolla and here is why: information asymmetry.

Before I get into what that means here is a quick example that was covered in the telephone conversation. Lets say my company sells widgets (something physical). A customer comes in and wishes to pay for a widget with Dwolla and since we are a Dwolla merchant we allow them to do so. Dwolla handles the transaction (debiting the customer's Dwolla account and crediting our Dwolla account). We give the customer their widget (we trust Dwolla that those funds were accounted for, more on that later). Days later, Dwolla takes the funds from our account because the customer claimed (to their bank) that the funds were not authorized to Dwolla. I, as the merchant, am now out a widget and the money I was paid for the widget because Dwolla was not able to properly detect the fraudulent user.

The reasoning Dwolla gives for the above is that fraud detection and customer identification is the responsibility of the merchant. What they don't seem to understand is that the merchant does not have the information to do such detection or identification. Dwolla is acting as the intermediary between the customer's bank accounts and personal information and the merchant. From the standpoint of the merchant, the USD transfered between the customer and merchant are "dwolla dollars" since the merchant trusts Dwolla that the transfer actually happened. The merchant has no way to query Dwolla for the customer's information or their credentials to verify that the bank account owner and customer are the same person. Dwolla hides this from the merchant (claiming to protect the customer) and by doing this prevents the merchant from having the information needed to tie accounts together and detect fraud the way Dwolla thinks we can. Even if the merchant identified the customer, they would not be able to verify anything about the linked bank accounts and where the funds come from. Fundamentally, Dwolla is trying to create "dwolla dollars" or virtual money based on the trust that they are backed by real dollars from real accounts without taking the accountability of doing so.

Since there is information that Dwolla has (and the merchant does not) and Dwolla is putting themselves between the customer and merchant, they are responsible for the funds they credit the merchant. If the merchant had to do the fraud detection and deal with customer bank accounts directly, they would not need Dwolla! Dwolla needs to be much more upfront about the "true" cost of doing business with them and that they will not worth with you to detect fraud or help you prevent it (since they can't prevent it themselves).

I understand that the USD banking system has chargebacks and that they are a reality of dealing with customer bank accounts. However, if you want to claim that fraud is the responsibility of the merchants, you must work with the merchants in linking customer accounts and verification otherwise your service is deceiving the very merchants you operate for. If you are a payment processor and are not absorbing the fraud, you don't understand your function properly and will just cost the merchant time and money. Eventually they will stop using you for a better alternative that does understand the risks and how to manage them. Maybe it won't be at $0.25 per transaction, and that might be the reality of the US banking system.

Many people don't understand why Bitcoins could be useful (beyond the realm of "pseudo anonymous" and "secretive") but the above is as clear cut example as any. Bitcoins allow merchants to not worry about fraud and create an entire payment system around the idea that once you are paid, the funds are yours! There is no period of uncertainty and thus you don't have to price in fraud into every part of the system.

pinning your hopes

2012-02-27T00:00:00+00:00

This is a post about the npm (node package management) and how I think it got versioning wrong in the package.json file. If you don't care about node there are still relevant items in this post about dependencies in development and deployment.

At first I was going to write a blog post about how the fuzzy versions are the wrong way to do it, but found this post that covered the topic. However I think this post, and others that talk about the fuzzy version issue are missing the core fundamentals behind WHY fuzzy versions are bad for development and deployment.

My argument stems from a few statements which I treat as axioms. I will try to address how each one relates to fuzzy versioning and why it matters.

Any change no matter how small is a "risk" to a deployed system
Consistency matters even for development
Deployment failures are better than runtime failures

Often when I hear about fuzzy versions in the node community it goes hand in hand with talk of semver. The idea of semver is good and can be used regardless of how you handle dependencies, but what semver does not expose is that even a change to version 0.0.x of a package can introduce a bug. For a dynamic language it could be as simple as a typo or a missing 'var' keyword. The point is not about the bug but that it has been introduced even in a version that is considered a "safe" point release. Now, if your library has not pinned its dependencies, this bug now becomes your bug. More critically (and as the referenced npm post states) running 'npm install' at two different times will yield two different codebases. The bottom line here is that semver is not a static analysis or a test tool but a way to communicate to another *person *about what types of changes they should expect and check for. It is not a substitute for a developer actually checking the changelog and doing testing. Maybe you don't care about this "risk" in production, but when you are writing a library, these risks are not for you to access.

When npm was first introduced it was touted as a tool for "development" versus "deployment". An argument developers make is that the fuzzy versions help them iterate quicker. I have yet to see "proof" of this but that is not the point. Fuzzy versions hurt development groups as well and for the same reasons as listed above. If I pull down your clean codebase and the versions are fuzzy, I may be getting versions which the original developer tested with. Now when I begin developing I am working with new "quirks" and more importantly wasting time debugging problems that no one else will be able to reproduce on their codebase until they wipe their dependencies and reinstall. I have not only wasted my time but other developer time simply because of a "harmless" point release. If you want to iterate quickly you can still do it, pinned versions in the package.json file do not stop you. Npm already has 'npm link' for local development. One of the less used features of npm versions is the ability to specify a tarball url or git repo to install from. THIS is how your team can iterate quickly on branches if it so chooses, but these should never be published to npm as such.

The final bullet point has to do with the generic idea of deployment failure. Another argument I have heard against using npm for deployment is that it is flaky, my firm has better (read different) ways, or that binaries are annoying. I am not trying to say your ways are worse or that the npm website can't go offline (which can be protected against), but what I am going to argue is that a failure during deployment is better than during runtime. In the case of binaries and compiled code, you will know right away if your deployment worked or did not. If it failed, you can take action immediately without the error being deferred to runtime. There is no "partial" deployment with npm, it worked or it didn't. If you use fuzzy versioning, the deployment can work just fine yet defer the error to runtime.

Npm is addressing some of these issues with the new npm shrinkwrap command. This creates yet another .json file in your repo. To me, this is just a "patch" on top of the real problem. Yes, it does "solve" the issue of pinned packages, but it does so in a poor way. Instead of keeping the packaging process simple with just the package.json file, another command and file are introduced. This seems like an admission that the versions should have been pinned from the start but instead of fixing that (which is probly impossible at this point) a new file is created. Nasty but arguably pragmatic.

This is not a post to hate on npm, in fact I think npm has many great features. I use npm daily for deployments and they always go smoothly (yes I use pinned versions). One last note about what makes package pinning great with npm: dependencies are localized! Each package maintainer can depend on their own desired package versions and test with those versions. The prominent people in the node community often develop many packages and don't want to update every single one when things change, however, they are in the nice position of being the maintainers and know what they are doing. When you are the consumer of a package, you don't always have such luxuries or trust and opening a communication channel is not the way to solve the problem. You cannot just tell someone they must vet changes by you or stick to semver (which I have shown isn't foolproof).

scraping broken SSL pages with node.js

2011-11-21T00:00:00+00:00

To collect the data for courseoff.com I scrape university websites on demand. This means that I have to perform http queries to the sites and then parse the resulting pages. Usually, this is not a problem as node.js has very simple APIs for performing both http and https requests. However, some schools have old webservers which make this task trickier.

Scraping a normal, up to date website, over SSL is not a problem; however, when you encounter a site with a broken web browser ssl implementation things go downhill fast.

You might see an error such as the following when trying to curl the url.

curl: (35) error:14077417:SSL routines:SSL23_GET_SERVER_HELLO:sslv3 alert illegal parameter

This was strange to me as my browser loaded the page just fine. Chrome does however give a hint as to something being wrong. When I click on the green lock icon, I get the usual certificate notice as well as an additional piece of information:

The connection had to be retried using SSL 3.0. This typically means that the server is using very old software and may have other security issues.

Clearly something is not right with the webserver here and that is what is causing curl, and subsequently my nodejs requests, to fail.

Doing some basic digging, I was able to find this nice little tidbit in the openssl documentation:

SSL_OP_ALLOW_UNSAFE_LEGACY_RENEGOTIATION

Allow legacy insecure renegotiation between OpenSSL and unpatched clients or servers. See the SECURE RENEGOTIATION section for more details.

Now that I had this option to try, I had to figure out a way to make node.js use it. Reading some code led me to understand that the 'Agent' is the object which handles the options for http(s) requests which are ultimately passed to the SSL context. When creating the agent, you pass in an options object, this object contains two fields which need to be used for this case: secureProtocol and secureOptions.

secureProtocol specifies which negotiation method to use
secureOptions are the flags passed to the context to change the behavior

My final agent object had the following form:

var agent = new Agent({
  secureProtocol: 'SSLv3_method',
  secureOptions: require('constants').SSL_OP_DONT_INSERT_EMPTY_FRAGMENTS
});

My https request options object just need to include the 'agent' key and have it set to the agent object I created. This filtered down to the underlying ssl context and set the context options. The request was a success!

This will only work with node.js >= 0.6.3 because the constants are only available after that. Other constants from the bug workaround section of the openssl documentation are also available for your needs.

References

ssl docs

http://www.openssl.org/docs/ssl/SSL_CTX_set_options.html

the tail of MongoDB

2011-06-12T00:00:00+00:00

I recently gave a talk at MongoNYC 2011 about using MongoDB as a messaging layer. The rationale behind doing something like this would be to maintain a log of all the messages passed between two clients. While there are many different IPC schemes available, I thought it would be interesting to build something simple on top of MongoDB using the tailable cursor feature. After giving the talk, I wanted to explore the performance characteristics of such a setup.

Before jumping into my benchmarking details, there are two important concepts to understand behind using MongoDB for message passing.

The tailable cursor gets its inspiration from the tail -f command in unix systems. For those unfamiliar with what that does, the idea is to open a file, listen for new additions to the end of the file, and print those. The program does not terminate when it reaches the end of the file, instead, it waits for more data. Using this approach, a simple message queue can be created with MongoDB. A producer creates messages and inserts them into MongoDB and then a consumer(s) is able to read those messages. While this can be simulated by keeping track of document IDs (in MongoDB and other database systems), in MongoDB the tailable cursor is actually supported server side and tracks the last returned document. This is much cheaper than having to constantly requery.

In MongoDB tailable cursors can only be opened on capped collections. This is because a capped collection is a fixed size and only allows insertions. This means that once the number of documents exhausts the collection size, newly written documents will start overwriting the first inserted documents. An important note about capped collections is that insertion order is the natural sort order. This means that when the tail cursor fetches documents, it will get them back in the order they were inserted. If you have more than one producer and insertion order matters, then you will need to either use separate collections or do your own reordering consumer side. For my examples, there is only one producer and thus natural (insertion) order is acceptable.

Now that we have some background on tailable cursors and capped collections, we can cover the benchmark setup. To perform the benchmark, I will have one producer and one consumer. The producer will get create a document of the format (Where the current time will have microsecond precision):

{ time: <current time in seconds> }

The producer will generate 100,000 of these messages and insert them into the collection. To avoid dealing with a slow consumer, the collection will be made big enough to hold all of the possible messages:

db.createCollection("messages", { size: 100000000, capped: true })

The producer is a simple python application:

#!/usr/bin/python

import time
from pymongo import Connection

conn = Connection()
db = conn.queues
coll = db.messages

start = time.time()

count = 100000
for i in range(0, count):
    coll.insert({ "time": time.time()})
    #This generates messages at a rate of about 3,900 msg/s
    time.sleep(0.0001)

end = time.time()
print("total: ", count)
print("msg/s: ", count/(end - start))

The consumer is a c++ client modeled after the default c++ tailable cursor example on the MongoDB page. It gets the system time upon reading a document and computes the latency between insert and read. The consumer is started before the producer:

#include <sys/time.h>

#include <mongo/client/dbclient.h>

using namespace mongo;

int main(int argc, char* argv[])
{
    DBClientConnection conn;
    conn.connect("localhost");

    // minKey is smaller than any other possible value
    BSONElement lastId = minKey.firstElement();

    // { $natural : 1 } means in forward capped collection insertion order
    Query query = Query().sort("$natural");

    cout << "loc,val" << std::endl;
    uint32_t i = 0;
    struct timeval tv;
    while( true ) {
        auto_ptr c = conn.query("queues.messages", query, 0, 0, 0,
                QueryOption_CursorTailable);
        while( true ) {
            if( !c->more() ) {
                if( c->isDead() )
                    break;
                sleepsecs(1);
                continue; // we will try more() again
            }

            const BSONObj& o = c->next();
            lastId = o["_id"];
            const double time = o["time"].Double();

            gettimeofday(&tv, NULL);
            const double curr = tv.tv_sec + tv.tv_usec / 1000000.0;
            cout << i++ << ", " << curr - time << endl;
        }

        // prepare to requery from where we left off
        query = QUERY( "_id" << GT << lastId ).sort("$natural");
    }

    return 0;
}

Running the consumer/producer pair generated the following latency graph:

The graph is not lines, but actually 100,000 points that represent the N-th packet versus the latency (read time - write time). The above graph has a standard deviation of: 0.29693s. While these results are not horrible, the sawtooth nature of the graph would indicate that there is something strange going on and that ideally, we can do much better and decrease the latency. I ran a simple consumer (without clearing the producer data) to see if the bottleneck was in the write side or read side:

Because the read only graph is essentially linear, it means that the consumer has no problem in reading all of the data if it is available and likewise, the producer did not have problems inserting the data. (The latency is irrelevant here as the data was inserted before the consumer had to read it). So given the above graph, we know the consumer can handle reading the data consistently if it is available, so the sawtooth pattern must emerge from what happens when new data is being inserted.

Taking another look at the Default C++ consumer graph, I noted that the consumer only goes back to ~1s latency when the previous latency was almost 0. This information, along with the c++ code which contains a sleep for 1 second was the aha! moment. When there are no more documents to read, the client waits for new documents to show up. Unfortunately, instead of being woken up when new documents are available, the default example uses a simple poll. This is expensive if our goal is to minimize latency. To test my theory I removed the sleep statement from the code and ran the consumer/producer pair again:

This method produced a standard deviation of 0.000739s. However, this is not the end solution as it has one major problem; it uses a tight loop which causes high CPU load locally and worse yet, thrashes the mongo server. Looking over the c++ driver API I found an interesting query option: AwaitData defined to: "If we are at the end of the data, block for a while rather than returning no data. After a timeout period, we do return as normal."

The AwaitData option sounded like just the thing I needed. I modified the query code to the following:

auto_ptr c = conn.query("queues.messages", query, 0, 0, 0,
    QueryOption_CursorTailable | QueryOption_AwaitData);

It is important to note that this causes the "more" cursor method call to block for a short time. If you cannot afford to block, this will not be a solution for you (see conclusion about some thoughts about evented systems)

And sure enough, when there were no more records to read, the local CPU would not spin. Yet I still noticed a problem. Since I start my consumer before the producer, I found that a bunch of re-querying was happening until the first record was inserted. This is due to a "dead" cursor. When the capped collection is empty, MongoDB does not keep a cursor open server side and thus the whole "tail" process never starts until at least one record is available. Given that I did not want to spin the local CPU or thrash the server, I inserted a sleep before the "break" when the cursor was "dead". This would cause a requery every 1 second until a cursor could be created (at least 1 record was inserted). While this did solve the spinning CPU problem, I found this solution caused a high initial latencies because of the sleep before the query:

Once the initial query happened, and a valid cursor obtained, then further queries were not needed and the latency remained very low. However the start up latencies were poor because we could be anywhere in the 1 second sleep before we are able to re-query.

To solve this problem, I used a dummy document to prime the collection and cursor. Given that even with a single document, a cursor would be created server side and the client would no longer have to query waiting for a valid cursor. While this solution is also not optimal, it does avoid having to keep querying the database in hopes of obtaining a valid cursor. So here with all the pieces in place (AwaitData, dummy document, and sleep before query):

This produced a standard deviation of 0.000662s, and never spun the CPU. The final c++ client code to produce this result (just the outer while loop):

while( true )
{
     auto_ptr c = conn.query("queues.messages", query, 0, 0, 0,
             QueryOption_CursorTailable | QueryOption_AwaitData);
     while( true ) {
         if( !c->more() ) {
             if( c->isDead() )
             {
                 // this sleep is important for collections that start out with no data
                 sleepsecs(1);
                 break;
             }
             continue;
         }

         const BSONObj& o = c->next();
         lastId = o["_id"];
         const double time = o["time"].Double();

         // handle the dummy document {time: 0.0}
         // yes, not a great comparison for doubles, just an example
         if (time == 0)
             continue;

         gettimeofday(&tv, NULL);
         const double curr = tv.tv_sec + tv.tv_usec / 1000000.0;
         cout << i++ << ", " << curr - time << endl;
     }

     // prepare to requery from where we left off
     query = QUERY( "_id" << GT << lastId ).sort("$natural");
 }

You can see how I bypass the dummy document used to prime the cursor as an example. I ran a similar consumer/producer test with no time delay on the producer (producing ~24,000 msg/s) and also obtained similar results with a standard deviation of 0.000753s.

Conclusions

Given the above latency measurements, I found that MongoDB tail cursors and capped collections performed much better than I expected. I was hoping for latencies in the 10 to 100 millisecond range but instead often got sub millisecond latencies for standard deviation with peaks of 5 milliseconds for the last run. Depending on your definition of "low latency" using MongoDB for basic message passing is quite viable and gives the added benefit of logging all of the passed messages for things like replay or catch up (if you have sequence numbers).

In performing this benchmark I encountered some pain points. The biggest one that may lead users astray is the incomplete example on the mongodb.org page (as of this writing). It does not mention the very necessary AwaitData flag, and also incurs a high latency due to the use of sleep.

Another problem (and something I consider a bug) is the behavior when there are no items in the collection. Depending on your use case and consumer/producer startup times, this may be a hidden issue that is hogging CPU time until a valid cursor is created. From my point of view, a valid cursor should be created immediately (even with no documents) that can then behave properly under the AwaitData condition.

And finally, it would be nice to expose an API that allows the c++ client to epoll (or some other notification scheme) when new documents are available. Since with the AwaitData call the "more" cursor method blocks for a bit, this becomes very unsafe in event driven systems which should not be blocking (or any system that should not block). Since there is a socket underlying the connection to the DB, this seems like a reasonable addition that would solve such a problem.

Additional Notes

All testing was done on a Core i7 920 running Ubuntu 10.10 using an SSD as the storage medium. I used the latest of the MongoDB master github branch as of June 9th.

Initially, I tested a simple python consumer, but it too suffered from the sleep problems and did not expose query options in the same way the c++ driver did. I stuck with the c++ driver as an example given the clarity in demonstrating the various gotchas in doing the benchmark.

I toyed around with the node-mongodb-native driver and think that the "streaming" aspects could make the callback API work a bit better but would need to be flushed out more with how the GET_MORE operation to the server is handled. I found that I could lock up the server if I was not careful with how many GET_MORE ops were being sent for the cursor.