How to get print output for debugging map/reduce in Mongoid?

Question

I'm writing a map/reduce operation with Mongoid 3.0. I'm trying to use the print statement to debug the JS functions. This is a troubleshooting suggestion from the MongoDB docs, e.g.:

reduce = %Q{
   function(user_id, timestamps) {
      var max = 0;
      timestamps.forEach(function(t) {
        var diff = t.started_at - t.attempted_at;
        if (diff > max) { max = diff; }
      });
      print(user_id + ', ' + max);
      return max;
    };
  }

 MyCollection.all.map_reduce(map, reduce).to_a

Unfortunately the output from the print statement shows up neither on the console nor on the log--it seems that this is suppressed somewhere between the DB, the driver, Moped or any of the intervening layers. Is there a way to turn this on?

Answer 1

It turns out the print statements logs to the MongoDB server log. On OSX, that is /usr/local/var/log/mongodb/mongo.log

Answer 2

Per the poster's comment, the first step is to make sure you are looking at the mongod server log. The easiest way to do this locally is by visiting the little-known HTTP interface to mongod: http://localhost:28017. This will work even if the server is not installed in its default location and, therefore, the log will not be in the default OS-specific location, e.g, /usr/local/var/log/mongodb/mongo.log on Mac OS X. See the docs for how to access this in non-standard deployment environments.

If that doesn't solve your problem, you'll have to go deeper into debugging MongoDB M/R, which is tricky for several reasons:

1. M/R jobs execute in a JS scope that is isolated from the rest of the DB
2. M/R jobs cannot write to anything other than the M/R output documents
3. The logger in MongoDB has discretion over what to emit to the logging stream

Here are my suggestions based on our extensive use of Mongo M/R in production:

Increase the logging level

Suddenly, some of the previously invisible print output will show up. Do it one level at a time until you start seeing it.

use admin
db.runCommand( { setParameter: 1, logLevel: 2 } )

Log levels vary from 0 to 5. See setParameter. You can also do this at server startup with -v, -vv, ..., -vvvvv.

Increase the profiling level to max (2)

I've found this useful, especially when combined with a high log level as it provides data exhaust (the profiling collection) that can be programmatically inspected. See the docs.

If you are running a very big M/R job, this may negatively affect performance.

Piggyback debug output through M/R

The idea is simple: add an array of objects with whatever debugging info you need, say in the _debug field, to all emitted documents and filter + concatenate as you see fit in the reduce phase. This way, the _debug arrays will end up in your output collection. You can even index them if you want to quickly find a particular problem.

Hope this helps. Good luck!