Inspecting Lucid Queries for Index Analysis

In This Lesson

We'll walk through how you can inspect specific or all Lucid queries within your AdonisJS application. We'll then use this to analyze a slow queries execution plan, determine an appropriate index to add, and add that index via a migration.

Created by: @tomgobich
Published: 1 year ago

Join the Discussion 0 comments

Be the first to comment!

Transcript

- Eventually we're all going to run into a scenario where the data that we're trying to query is coming back too slow. Either our data set has gotten too large
or the query itself is inefficient. So for example, here I have a paginated list of posts. There's 743,000 within the filtered results set and I have 30 per page coming through.
If I were to refresh this page, you can see that takes a second to run. So it's not super snappy. What we're going to take a look at here today
is how we can inspect the actual SQL that's running with this query via Lucid. Analyze it with Postgres explain analyze so that we can see the actual plan that's being executed and how long it takes.
And then we will also create an index to boost the speed of this query up via a migration. The query itself looks like this. So we're reaching through our post model
to get the ones where the state is public. The publish at is less than or equal to the date time now. And then we're ordering by the publish at descending. To see the actual SQL that's being run here though,
there's a few different options that we have. So first we can do it on a per query basis. And to do that, we just need to chain in somewhere, debug and set that flag to true.
However, if we just set this and I have the integrated terminal within Visual Studio Code running here. So I'll pop this open. If we just add this and we come back into our browser,
refresh and inspect our terminal, we're going to see that we get nothing printed out here. What we need to do is actually listen for the event that this is now firing. We can either do that manually
or what I like to do is just jump into the database config and there's a flag in here that will do it automatically for us. And that is pretty print debug queries. So we just set that to true, give that a save.
And you can see that the browser already went ahead and refreshed thanks to the hot module reloading. And we have two queries printed out. The first one is a count against our post table with the same filter set.
And the second one is our actual paged data. So this one's getting the overall count of that 700,000 plus that we're displaying to discern how many pages of content we have
via the pagination. And then this one is the specific page that we're displaying. To the left of this in parentheses, we can see how long this query took to run. So we have 238 milliseconds.
It's not overly long, but it's not super snappy. And then to the right of this query, we have our parameters being passed into it. So you'll notice that we have these question marks throughout the query itself.
Those are the parameter placeholders. So the first question mark is going to get the zero index of this array. The second question mark will get the one index
or the second item in the array, so on and so forth. For this lesson, we're just going to focus on this query right here, though really the index for both of these would be relatively similar
since they are filtering by the exact same data. So what I'm going to do is just copy this query and its parameters. And so that we can easily see everything in a pretty fashion, I'm going to do this within TablePlus here.
So I'm going to drop this query in, and I'm going to drop our parameters down a couple of lines and patch them into their placeholders. So first we have the state, set the public.
Then we have our publish at. I'm just going to drop down here and grab the actual value from this. So I don't have to type all that out, plop it in.
And then we have our limit of the number per page that we want, which is 30. All right, now we can get rid of those parameters. And I'm going to beautify this. And if we run it, we'll get back the exact same data
that our query is getting via Lucid. And we can confirm that that took 250 milliseconds to run. If we prefix this, and this is going to vary depending on the database driver that you're using.
Here I'm using Postgres, so that is explain analyze, but we can explain analyze on this select. And I'm just going to beautify that once more to see the actual execution plan
that Postgres is deciding to take for this query. So if we run this, we can see the query plan come through now instead of our actual results. And if I just expand this information out a little bit.
So down here at the bottom, we can see the execution time of 261.6 milliseconds. We see the total time that it took to plan this query out, 0.098 milliseconds.
And then above this is the actual plan that it executed. And where this really starts, where we really care about this is down here at the parallel sequential scan against our post table.
So that means that it's going through the entire dataset and not using an index. So if we take a look at the entire dataset that we have here it's about 5.9 million. So that's quite a few rows to go through.
And within this explain analyze will show us the estimated costs that it thinks it will take to execute this query. And then it will actually execute the query
and give us the actual cost that it needed in order to actually properly execute the query. So this will actually run the query. So be careful if you're doing an insert update or delete there.
So 0.00 here is the cost to get back the first row. And then the 323544.50 is the cost to get all of the rows.
The 312,863,000 rows that it's showing here are the estimated number of rows that it will return back for this node. The width is the planner's estimated average width in bytes for the rows.
And then the loop says the number of times that the node was actually executed. And below that we have the actual filter being applied, just kind of listed out there. And the number of rows that that filter removed.
Above our parallel sequential scan, we have our sort key, which is publish at descending. And this has similar cost, row,
and actual cost and row information along with it as well. So how do we take all of this and put it into an actionable item? Well, first what we wanna do is take a look
at the actual time of execution for each of these nodes. At the top, our gather merge started with its first row
at 259 milliseconds and ended at 261 milliseconds. So that took very little time compared to some of our others.
Our sort took even less time at 254 compared to 254. When we get to our parallel sequential scan, however,
that started at 0.12 and ended at 241. So the parallel sequential scan is the one that took the longest to actually run. The next thing that we can do
is take a look for telltale signs, like a parallel sequential scan on a large dataset. We have millions of rows in here and that's a large dataset. So doing a parallel sequential scan on that
is going to be less efficient compared to an index. But what we can gather from this is that an index on our state and publish at, with our publish at having an index in descending fashion,
would greatly benefit this query. So let's actually create that index directly within TablePlus here so that we can see it with our explain analyze
to see exactly what the execution time benefits are with the index in place. So let's create index and I'll prefix this with post, which is the table name.
And then this is going to include our state column as well as our publish at column and then suffix it with IDX to note. On our posts table,
again, applying that towards our state column and the publish at column. And we can order the publish at in descending fashion with this index as well. All right, let's go ahead and run this.
And it will take a second to actually go through and apply this index to all of our 5.9 million plus rows. Okay, perfect. It's now created it and took about 5.8 seconds.
So if we run our explain analyze once more, what we should see is that the decimal point is practically moved several places. So rather than taking 200 and something milliseconds,
it's now 0.275 milliseconds. That's a drastic improvement. And with this in place, if we were to jump back into our browser here and refresh our data,
you'll see that that's coming back much quicker. Since we have our debugging on still, if we jump back into Visual Studio Code here, we can see all of these queries printed out as well.
So we have our original query coming through at that 238 milliseconds. We have the first uncached query with our index applied taking 6.7 milliseconds.
And then we have the subsequent cached query results of 1.73 milliseconds, 1.61 milliseconds, and then back to 1.78. So a considerable improvement.
What we don't want to do though, is leave this index having been created via an external entity. What we want this to do is be created via a migration. So I'm gonna go ahead and drop this.
And the reason why we want this to be created via a migration is so that any other users that pull our application down and run our migration to get their database set up, we want them to also have this index
applied to their database. And we also need this to go out to production as well. So let's stop our server there. I'm gonna clear this out and let's do node ace,
make migration, make this an alter migration. And this is gonna go against our posts table. All right, we can jump into our database, our migrations,
and go down to that alter posts table migration. Now, traditionally what you would do to create an index here is to use the table index method, apply the column name in.
So if we were just doing state, we'd call it the state, and then we can optionally give it a custom index name as well here. On the inverse side then what you would do is table.drop index.
Again, this takes in the same arguments. So whether it's a composite index, you could pass in an array of names or a single states, and then the index name there
to drop that on the inverse downside. But what we need to do is actually run this as a raw SQL statement because connects.js,
which runs underneath the hood of Lucid, doesn't actually allow us to order the publish out within our index with this approach. So we can do this via this schema.raw.
Then we just pass the raw statement in here. And what I'm gonna do is jump back over to TablePlus, and I'm just gonna go ahead and copy that and paste it in there. Then on the downside, we can do the relatively similar,
the schema raw, and I'm just gonna paste the whole thing in there, cut that back down to just the name. Switch to create to drop, and now we should be good to go. Before we boot our server up though,
let's quickly discuss the alternative approach to logging out our queries. So here we did it on a per query basis by adding the debug true in on the specific query we're looking at.
But we can also do that for all queries within our application, within our database config as well. Inside of the connection that we're working with, there is this debug option. We just set that to true.
And now all of the queries that are run by our application will get logged out into our console. Okay, so let's jump back into our terminal here,
node ace migration run to run our migration. And look at that, you can actually see that already taking place to grab which migrations have already run.
And we can see the actual create index statement run there, followed by our migration success statement there, and then the unlock on our Postgres right there.
So we already know that our entire query set log is taking place. I'm gonna go ahead and boot my application back up. We can confirm via TablePlus
that the index actually took place by jumping back into our table, going over to the structure, and I'll need to refresh since it's changed since it last loaded.
And we should now see our posts state publish at index applied here as a B-tree index algorithm with the state and publish at descending columns.
So we are able to verify that this is actually taking place inside of our database. If we take a look at the explain analyze once more, which should look the exact same as it did whenever we had our index in place,
taking 0.272 milliseconds. And if we jump back into our application and refresh, it is indeed happening nice and snappily.
If we jump back into Visual Studio Code one more time, we can again still see the same queries printed out since we now have all of our queries printing out.
And we can stop this, clear it out, node ace migration, roll back, and we should see that the index gets dropped right there.
So that worked properly. And we can confirm that once more inside of TablePlus by refreshing and away it goes that index. So perfect. So that's how you can get to the root of the actual SQL
that's running with your Lucid queries and how you can create indexes inside of migrations to help improve their speed if needed.

AdonisJS Scenarios

3 Lessons

37m 37s

Stop losing your best ideas!

Use our integrated note feature to capture and organize your key insights. Take a note at any timestamp and jump instantly back to that moment in the video with a single click.