Como monitorizar consultas lentas en MongoDB

Después de haber trabajado con indices en semanas anteriores, hoy os vamos a explicar como detectar cuellos de botella en nuestras aplicaciones causados por consultas lentas. Uno de los grandes problemas que tenemos a la hora de programar aplicaciones es como optimizar nuestras consultas. Mongo, de forma automática, monitoriza todas las consultas que tienen una duración mayor a 100 milisegundos y las guarda en un fichero de log, esto nos puede ayudar bastante para optimizar nuestras aplicaciones. Para poder consultar dichas queries tenemos que lanzar Mongo como demonio y especificar en que fichero se guardaran.

Para ello vamos a levantar el demonio de Mongo con mongod en segundo plano añadiendo al final &, especificando con --dbpath donde vamos a almacenar nuestras bases de datos, con --port le indicamos que levante la instancia por el puerto especificado y con --logpath le indicamos en que fichero queremos nos guarden los log.

mongod --dbpath /home/hispabigdata/data/ --port 27017 --logpath /home/hispabigdata/data/log/hispabigdata.log &

Ahora accedemos a la consola de mongo y vamos a crear una colección llamada ConsultaLenta con 10.000.000 de registros, este proceso puede durar bastante tiempo, así que tened paciencia.

for (var i=0; i < 10000000; i++){
 db.ConsultaLenta.insert ({"_id":i, "nombre":"HispaBigdata"+i, "fecha": ISODate()});
}

Por otro lado vamos a abrir un terminal y vamos a monitorizar el fichero de log que hemos especificado anteriormente:

tail -f /home/hispabigdata/data/log/hispabigdata.log

En la consola de mongo vamos a realizar una consulta por el campo nombre:

db.ConsultaLenta.find({"nombre":"HispaBigdata150000"});

Dependiendo del equipo en el que ejecutemos esta prueba, la consulta tardara mas o menos, una vez acabe, en el terminal donde estamos monitorizando el log podemos ver datos relacionado con la consulta como el numero de documentos leídos en nscanned y el tiempo que ha tardado en milisegundos.

Si creamos un indice al campo nombre, por ejemplo veremos como nuestra consulta se ejecuta casi instantáneamente, este proceso va a ser bastante lento y bloquearia la colección por lo que recomendaría crear dicho indice en segundo plano usando si vamos a hacer en algun sistema de producción:

db.ConsultaLenta.ensureIndex({"nombre":1},{background: true});

Al crear el indice podemos ver como en nuestro fichero de log añade las entradas correspondientes a la creación de dicho indice:

Por lo que si lanzamos ahora la misma consulta creada anteriormente veremos como tarda muy poco. De esta forma, cuando detectemos que alguna aplicación presente lentitud, podemos consultar en nuestro fichero de log si existe alguna consulta que este tardando mas de la cuenta.