4 min read
Latest Articles
- Accessing Large Language Models from PostgreSQL
- 8 Steps in Writing Analytical SQL Queries
- 4 Ways to Create Date Bins in Postgres: interval, date_trunc, extract, and to_char
- Crunchy Postgres for Kubernetes 5.7: Faster Backups, Automated Snapshots, Postgres 17 and More
- pg_parquet: An Extension to Connect Postgres and Parquet
Postgres Traceability: Use SQL Comments Like a Stacktrace
Have you traced a sql statement back to the source application? Of course you have! Was it time consuming? Probably! SQL queries can hide in plain sight.
If you've read through any of Crunchy's advice on query performance or healthy databases you know there's a goldmine of optimization waiting for you in your database. When using an ORM, the queries are obfuscated, and tracing a specific query to the application code can be challenging.
Using Ruby as an example below (BTW, I <3 Ruby; I will see you at RailsConf!), ORMs generally look like the following. If the source of your performance issues is the following, how would you know?
Message
.where(recipient_id: params[:id])
.includes(:recipient, :sender)
.order(sent_at: :desc)
The SQL that is generated looks nothing like the ORM code that is written. The above code will output the following SQL statements:
-- get messages
SELECT "messages".* FROM "messages" WHERE "messages"."recipient_id" = $1
ORDER BY "messages"."sent_at" DESC
-- get recipient
SELECT "users".* FROM "users" WHERE "users"."id" = $1
-- get senders
SELECT "users".* FROM "users" WHERE "users"."id" IN
(/* list of args whose length depends on number of senders*/)
But that's just Ruby, right? Node's Prisma …
I built a similar structure in the Prisma ORM, and ran the following code:
prisma.message.findMany({
orderBy: [
{
sent_at: 'desc',
},
],
where: {
recipient_id: 10088,
},
include: {
recipient: true,
sender: true,
},
})
The queries generated look like the following:
-- get messages
SELECT "public"."Message"."id", "public"."Message"."message",
"public"."Message"."recipient_id", "public"."Message"."sender_id",
"public"."Message"."sent_at", "public"."Message"."created_at",
"public"."Message"."updated_at" FROM "public"."Message"
HERE "public"."Message"."recipient_id" = $1 ORDER BY
"public"."Message"."sent_at" DESC OFFSET $2
-- get recipient
SELECT "public"."User"."id", "public"."User"."email",
"public"."User"."name", "public"."User"."created_at",
"public"."User"."updated_at" FROM "public"."User" WHERE
"public"."User"."id" IN ($1) OFFSET $2
-- get sender
SELECT "public"."User"."id", "public"."User"."email",
"public"."User"."name", "public"."User"."created_at",
"public"."User"."updated_at" FROM "public"."User" WHERE
"public"."User"."id" IN
(/* list of args whose length depends on number of senders*/) OFFSET $25
What do SQL comments do?
Enough with the ORM bashing! But, you get the point right? A system with high load, slow responses, a database log flowing with slow queries, then, a land-mine of a query is thrown into the database. How can we fix this? How can we point you in the right direction?
Use SQL Comments!
What does a commented SQL statement look like?
-- get messages from Rails using
SELECT "messages".* FROM "messages" WHERE "messages"."recipient_id" = $1
ORDER BY "messages"."sent_at" DESC /*application:CustomerFacingFrontEndApp,
line:/app/controllers/messages_controller:5:in `<main>'*/
By looking at the comment, we know the query was run by executing line 5 of the MessageController
from the CustomerFacingFrontEndApp
. Query comments are recorded in your slow query logs and when using pg_stat_statements
.
NICE! So, how can we do that? It all depends …
Python, Java, Node.js, & PHP:
- sqlcommenter, this project has a wide-breadth, so it may or may not be plug-and-play for your environment, yet it is a good starting point.
Rails (which I love) has 2 native features in Rails 7:
- QueryLogs
- Query annotations
- Older Rails versions can look at marginalia
Prisma:
GoSQL:
- Write your own comments in the SQL :)
But wait, there is more
Combine SQL Comments with the following Postgres features, and you'll level up your traceability:
pg_stat_statements
- record query performance to a Postgres tablelog_min_duration_statement
- if a query takes longer than a specified time, record query in Postgres logs.auto_explain
- if a query takes longer than a specified time, record the query execution plan in Postgres logs.
Below, I have a query below that returns the user_id
with the most received messages. I've also added the Ruby on Rails annotate
method to track how a slow query is being executed:
Message
.group(:recipient_id)
.select("recipient_id, COUNT(id) AS max_received")
.order("max_received DESC")
.limit(1)
.annotate("Github Issue #345")
In my logging management system, I can go search for "Github Issue #345" (Of course, you should tie this back to your issue tracking system!). Your log management system would show the following:
LOG: duration: 248.578 ms plan:
Query Text: SELECT recipient_id, COUNT(id) AS max_received
FROM "messages" GROUP BY "messages"."recipient_id"
/* Github Issue #345 */ ORDER BY max_received DESC LIMIT $1
Limit (cost=126246.71..126246.72 rows=1 width=12)
-> Sort (cost=126246.71..126401.77 rows=62022 width=12)
Sort Key: (count(id)) DESC
-> Finalize GroupAggregate (cost=110223.35..125936.60 rows=62022 width=12)
Group Key: recipient_id
-> Gather Merge (cost=110223.35..124696.16 rows=124044 width=12)
Workers Planned: 2
-> Sort (cost=109223.33..109378.38 rows=62022 width=12)
Sort Key: recipient_id
-> Partial HashAggregate (cost=94535.88..104286.23 rows=62022 width=12)
Group Key: recipient_id
Planned Partitions: 4
-> Parallel Seq Scan on messages (cost=0.00..34642.25 rows=934925 width=12)
Yuck! This query just performed a bunch of table-scans over 934,925 rows multiple times!
Step #1, read Postgres Indexes for Newbies, Step #2: add indexes, Step #3: measure improvement or revert, Step #4, rinse and repeat.
Where to start?
Even if you don't have slow queries now, go ahead and start commenting your queries. Your future-self will thank your past-self.
Related Articles
- Accessing Large Language Models from PostgreSQL
5 min read
- 8 Steps in Writing Analytical SQL Queries
8 min read
- 4 Ways to Create Date Bins in Postgres: interval, date_trunc, extract, and to_char
8 min read
- Crunchy Postgres for Kubernetes 5.7: Faster Backups, Automated Snapshots, Postgres 17 and More
4 min read
- pg_parquet: An Extension to Connect Postgres and Parquet
4 min read