Experiment: Putting DEBUG Comments In Your Sequelize-Generated Queries In Node.js
As I wrote about over a year ago, I've made it a best-practices habit to add a "DEBUG" comment before most of my SQL statements. This DEBUG comment, while having no affect on the query itself, will show up in the MySQL general_log and, more importantly, the slow_log (aka, the slow query log). This makes it much easier to debug database performance bottlenecks because the source of the offending query can be located quickly based solely on the log table. This is easy to do if you're writing raw SQL; but, if you're using an ORM (Object-Relational Mapper) like Sequelize in Node.js, there is generally no opportunity to inject a SQL comment. As such, as an experiment, I wanted to see if I could augment Sequelize's internal query generator as a means to expose a DEBUG comment hook.
To be clear, when I talk about a DEBUG comment in my SQL, the comment usually contains the location of the query originator inside the application's data-access layer. So, for example, a DEBUG comment might look something like this:
/* DEBUG: userRepository.getById(). */
... or, it might look something like this:
/* DEBUG: orderGateway.getAllOrdersPlacedInPreviousMonth(). */
The idea is that the DEBUG comment, when it shows up in the query logs, is supposed to give your data-services team and database administrators a jumping-off point for investigation. This is especially important for ORMs because the generated query is often-times so insanely verbose that picking it apart is, unto itself, a Herculean task.
With an ORM like Sequelize, we're not writing the raw SQL - we're providing "options" to the Sequelize instance. The Sequelize instance then takes those options and transforms them into a meaningful SQL query that it can use to pull back the necessary data. This means that we can't just prepend arbitrary SQL constructs like a Comment. Instead, we have to supply the DEBUG comment as an option, and then hope that Sequelize applies that comment to the underlying query.
Of course, Sequelize won't do this out of the box; but luckily, Sequelize was built to expose its internals. In order to work with different SQL technologies like MySQL, Microsoft SQL Server, and Postgress, Sequelize uses an abstraction layer that depends upon a "dialect" implementation that is responsible for generating the technology-specific query syntax. And, once instantiated, the Sequelize instance exposes the selected dialect that is being used under the hood. This means that, after we create our Sequelize instance, we can reach down into the current implementation and proxy the calls that generate SELECT statements.
In this experiment, I'm focusing on the SELECT statements because the hook seemed more obvious. But, I would think this same approach is applicable to other SQL operations (like UPDATE and DELETE). That said, in the following code, I'm creating a proxy invocation to the underlying selectFromTableFragment(). This is the dialect-specific method that is responsible for generating the SELECT clause of a SELECT query. As such, it's the perfect place to add a hook for an optional DEBUG comment:
// Require the core node modules.
var Sequelize = require( "sequelize" );
// ----------------------------------------------------------------------------------- //
// ----------------------------------------------------------------------------------- //
// Setup our Sequelize instance.
var sequelize = new Sequelize(
"testing", // Database.
"test", // Username.
"test", // Password.
{
host: "localhost",
dialect: "mysql"
}
);
// Define the ORM (Object-Relational Mapping) models.
var FriendModel = sequelize.define(
"FriendModel",
{
id: {
type: Sequelize.DataTypes.INTEGER(0).UNSIGNED,
allowNull: false,
primaryKey: true,
autoIncrement: true
},
name: {
type: Sequelize.DataTypes.STRING,
allowNull: false
}
},
{
tableName: "friend",
createdAt: false,
updatedAt: false
}
);
// ----------------------------------------------------------------------------------- //
// ----------------------------------------------------------------------------------- //
// Under the hood, Sequelize using an abstraction layer for generating the SQL
// statements so that it can be used with different dialects of SQL. This provides us
// with a way to override parts of the SQL statement generation by proxying calls to
// the underlying "Query Generator". In this case, we're going to proxy calls to the
// "selectFromTableFragment" method so that we can insert an optional COMMENT prefix
// before the SELECT statement.
// --
// CAUTION: Using {block} here to create block-scoped variables.
{
// Get a reference to the dialect-specific query generator. This is what Sequelize
// uses to assemble the various components of the resultant SQL statements.
const queryGenerator = sequelize.getQueryInterface().QueryGenerator
// Get the original "SELECT" fragment generator so we can proxy it.
const oldSelectFromTableFragment = queryGenerator.selectFromTableFragment;
// Provide a proxy implementation that will look for an {options.comment} value.
queryGenerator.selectFromTableFragment = function( options, model, attributes, tables, mainTableAs ) {
var baseFragment = oldSelectFromTableFragment.apply( this, arguments );
// Prepend SQL comment if option is present.
var fragment = options.comment
? ( prepareComment( options.comment ) + baseFragment )
: baseFragment
;
return( fragment );
};
// I prepare the comment for use as a query prefix.
function prepareComment( comment ) {
var sanitizedComment = String( comment )
.replace( /[\r\n]+/g, " " ) // Strip new lines.
.replace( /\/\*|\*\\/g, " " ) // Strip comments.
;
return( "/* " + sanitizedComment + " */ " );
}
}
// ----------------------------------------------------------------------------------- //
// ----------------------------------------------------------------------------------- //
// Now, let's try running a few commands that should use the SELECT query.
FriendModel
.findById(
3,
{
comment: "DEBUG: Testing .findById()."
}
)
.then( console.log )
;
FriendModel
.findOne({
comment: "DEBUG: Testing .findOne().",
where: {
id: {
$in: [ 4, 5 ]
}
}
})
.then( console.log )
;
FriendModel
.findAll({
comment: "DEBUG: Testing .findAll().",
where: {
$or: {
id: 1,
name: "Libby"
}
}
})
.then( console.log )
;
As you can see, after we define our Sequelize instance and our Models, we're reaching down into the current dialect implementation to access the SELECT statement generator:
sequelize.getQueryInterface().QueryGenerator.selectFromTableFragment
We then overwrite this method with a new method that proxies the invocation. First, it invokes the original implementation, generating the base SELECT statement. Then, it prefixes the resultant SELECT statement with a DEBUG comment if the options.comment property exists.
Now, when we run the above code and try the following methods:
- .findById()
- .findOne()
- .findAll()
... we see the following logging in the MySQL general_log table:
As you can see, the options.comment value, if present, was prepended to the resultant SELECT statement. This makes it much easier for your database administrators to debug these queries when they show up in the general_log and slow_log because it gives them something to search for (or even a specific file to open).
I can't emphasize enough how helpful these DEBUG comments really are. As someone who spends a lot of time trying to understand why other people's queries examined 95,000 records in order to return a single row, having some indication of where the query originated is priceless. And, thankfully, with the way Sequelize is constructed, we can monkey patch this ability right into the ORM so that even ORM-generated queries can be administrator friendly.
Want to use code from this post? Check out the license.
Reader Comments
Great Idea Ben!
The implementation is pretty simple as well.
Its already running on my code base.
Wish someone submitted a PR on sequelize, just to make sure it won't break in future versions.
@Eran,
Thank you, good sir. Yeah, it would be awesome if there as a "comment" option that they would just take care of internally. It's "simple enough" to handle it as an interceptor on the QueryGenerator; but, that makes it brittle for sure. Very tightly coupled to the current implementation of the dialects.
I'd like to see if I can wrap this up in a Plug-in for the Sequelize module, with some more thorough integration (putting that on my ToDo list).
@All,
I wrapped this concept up in my first npm package, sequelize-comment:
www.bennadel.com/blog/3279-sequelize-comment-a-sequelize-plug-in-that-injects-comments-before-your-sql-statements.htm
This uses the same general approach, but is applied to all of the CRUD fragment-generation methods.