Timing Your Queries in Knex.js for Node.js

While developing web applications, I keep a close eye on performance issues, particularly in database queries. In my latest project, I’ve been using Knex.js, a SQL query builder for Node.js.

I developed a method of logging the queries executed by Knex.js as well as the execution times for each query. This method can be applied to nearly any application that uses Knex.js, and it uses a few features of Knex.js that I didn’t notice immediately, so I thought I’d share this small but useful bit of code.

Using Knex.js Events

In Knex.js, you can use .on() to interface with different events regarding your queries. To capture the execution time of a query, I used the “query” event, which fires when a query is called, and the “query-response” event, which fires after the database responds successfully.

By using these event hooks, I’m able to get information about the queries the server is executing, such as the unique identifier of the query as shown below:

knex.on('query', (query) => {
    console.log(`Executed a query: ${query.__knexQueryUid}`);
  }) 
  .on('query-response', (response, query) => {
    console.log(`Received a response from: ${query.__knexQueryUid}`);
  })

Timing the Queries

Having access to these two events, I’m able to record the start and end time for each query. To time the queries, I used a library called performance-now which can get fairly accurate results within a few milliseconds. Also, since Knex.js will execute queries asynchronously, I recorded the order of when the queries are sent to the database. I find it helpful to see the queries in the order in which they are called instead of when they respond.

import now from 'performance-now';

// The map used to store the query times, where the query unique
// identifier is the key.
const times = { };
// Used for keeping track of the order queries are executed.
let count = 0;

knex.on('query', (query) => {
    const uid = query.__knexQueryUid;
    times[uid] = {
      position: count,
      query,
      startTime: now(),
      // I keep track of when a query is finished with a boolean instead of 
      // presence of an end time. It makes the logic easier to read.
      finished: false,
    };
    count = count + 1;
  }) 
  .on('query-response', (response, query) => {
    const uid = query.__knexQueryUid;
    times[uid].endTime = now();
    // Mark this query as finished.
    times[uid].finished = true;
  })

Printing the Queries and Times

Now that I’ve recorded the times of my queries, I can print them to the console. Logging the queries that Knex.js executes is pretty straightforward:

const printQueryWithTime = (uid) => {
  const { startTime, endTime, query } = times[uid];
  const elapsedTime = endTime - startTime;

  // I print the sql generated for a given query, as well as 
  // the bindings for the queries.
  console.log(query.sql, ',', `[${query.bindings ? query.bindings.join(',') : ''}]`);
  console.log(`Time: ${elapsedTime.toFixed(3)} ms\n`);

  // After I print out the query, I have no more use to it, 
  // so I delete it from my map so it doesn't grow out of control.
  delete times[uid];
};

However, I prefer to see queries printed out in the order I called them, rather than when the database responds with the results. This makes debugging database calls easier since I can usually predict the order the server should be calling the queries rather than when the responses should come back. To do this, I updated my “query-response” event hook to this:

.on('query-response', (response, query) => {
  const uid = query.__knexQueryUid;
  times[uid].endTime = now();
  times[uid].finished = true;
  const position = times[uid].position;
  
  // Print the current query, if I'm able
  printIfPossible(uid);

  // Check to see if queries further down the queue can be executed,
  //in case they weren't able to be printed when they first responded.
  printQueriesAfterGivenPosition(position);
})

Again, the code for these two print functions is fairly straightforward:

const printIfPossible = (uid) => {
  const { position } = times[uid];
  
  // Look of a query with a position one less than the current query
  const previousTimeUid = Object.keys(times).find(key => times[key].position === position - 1);

  // If we didn't find it, it must have been printed already and we can safely print ourselves.
  if (!previousTimeUid) {
    printQueryWithTime(uid);
  }
};

const printQueriesAfterGivenPosition = (position) => {
  // Look for the next query in the queue
  const nextTimeUid = Object.keys(times).find(key => times[key].position === position + 1);

  // If we find one and it is marked as finished, we can go ahead and print it
  if (nextTimeUid && times[nextTimeUid].finished) {
    const nextPosition = times[nextTimeUid].position;
    printQueryWithTime(nextTimeUid);
    
    // There might be more queries that need to printed, so we should keep looking...
    printQueriesAfterGivenPosition(nextPosition);
  }
};

Now, whenever I run a query, I should see the execution time of each query in my console like this: