Postgres in Production Special Series: How to Query pg_stat_statements to Find Slow and Expensive Postgres Queries (Part 7)

In the final part of this special Postgres in Production deep dive series, Ryan Booz does something the first six episodes rarely did: he queries pg_stat_statements itself. This episode covers why your first stop during an incident should actually be pg_stat_activity, two ways to get a usable window out of cumulative metrics (diffing snapshots, or resetting and re-querying), which columns to order by and why the slowest query is not always your problem, and what to look for when you pick a monitoring tool to keep this history for you.

Share this episode: Click here to share this episode on LinkedIn. Feel free to sign up for our newsletter and subscribe to our YouTube channel.

---

Transcript

A quick recap

Believe it or not, through these last six episodes we’ve rarely queried the data itself. We’ve talked about what pg_stat_statements is and isn’t (Part 1), how query texts get normalized (Part 2), where the texts themselves are stored and how that can get contentious (Part 3), and we’ve looked at the source code to see exactly what happens once your query finishes executing (Part 4). We covered configuration (Part 5) and, in the last episode, how to identify a high cardinality query workload (Part 6).

In this episode, we’re finally going to query the view itself and talk about a few things you can do to identify the queries that need your focus right now.

pg_stat_statements keeps no timeline by itself

The thing to remember through this whole conversation is that we’re still talking about data exposed through a view, or a set returning function, and it’s simply cumulative. There is no timeline to the information stored in pg_stat_statements.

To get that kind of timeline value, you would have to take regular snapshots, figure out how to calculate the deltas between those snapshots, and preserve history outside of pg_stat_statements so you could go back and see the status of a query in the past, or how it trends over time. And your solution would have to account for resets, evicted queries, and new queries as they come in. How do you store them and identify their metrics over time?

All of this culminates when the moment happens. You get the call that the database or the application is slow. You know you have pg_stat_statements turned on, but you haven’t been collecting the history in a tool. What do you actually do in that moment?

Why to query pg_stat_activity before pg_stat_statements

Believe it or not, my first suggestion is not to query pg_stat_statements. Instead, you should be querying pg_stat_activity. Why do I say this?

People often first learn about pg_stat_statements in the moment when there’s a problem happening right now in their database. And one of the very first things we learned in this series is that pg_stat_statements is not about current, real-time activity. It only records metrics when the query has finished executing.

Say the situation is an ad hoc query that is running right now and has not yet completed. The metrics for that query will not exist in pg_stat_statements, at least if the query has never run before. And even if it has, you don’t know the situation of this specific execution right now.

pg_stat_activity won’t give you execution metrics either, but it will tell you whether there’s something to investigate that’s outside of pg_stat_statements. The example query I use simply looks for the currently active processes that are not this query, and returns the process ID, the query ID if it exists, the user name, the application, and specifically the transaction and query duration:

SELECT
    pid,
    query_id,
    usename,
    application_name,
    state,
    now() - xact_start AS transaction_duration,
    now() - query_start AS query_duration,
    wait_event_type,
    wait_event,
    query
FROM pg_stat_activity
WHERE state = 'active'
AND pid <> pg_backend_pid()
ORDER BY query_duration DESC;

You’re looking for queries that have been running for at least multiple seconds, maybe much longer. That’s a good indicator that the thing you’re looking for isn’t yet about pg_stat_statements.

Let me show you a quick example. I’m using the Bluebox database I’ve talked about previously, with its load testing process running against it to produce some queries. This particular copy is on a VM I host, using Patroni for replication. As I query the database there’s not a lot of load, and you can see the replication process running.

I keep querying until I catch an example result. Many of these queries run sub-millisecond, so they’re hard to catch, but here I have the actual duration of the transaction and the query, which helps identify something long-running outside of the processes we can’t control, like replication. If something stands out, we can look at the query text and see whether it sparks an idea of what might be happening: is this an application? Is this ad hoc? And we can see the query ID. In this case it’s the exact same normalized query running two different times, because the load test triggers two processes to run the same query.

Using pg_stat_activity this way is a gut check: is this a pg_stat_statements problem that you can identify, or is something abnormal happening right now on your server, with pg_stat_statements secondary?

The safer approach: diff two snapshots of pg_stat_statements

Once you’ve determined it’s not some abnormal query at this moment, it’s time to look through pg_stat_statements and query it in a way that bubbles to the top what might be going on. Maybe it’s not a long-running query, but a process running a lot of the same query over and over.

The first way to do this, if you don’t have a tool already set up, is what I call the safer approach. Take two snapshots some length of time apart, then diff the metrics that matter for what you’re trying to identify. It’s as simple as creating a temp table out of pg_stat_statements, waiting 10 seconds, maybe 30 seconds, or a minute, whatever you feel is necessary to capture the workload, then taking a second snapshot and comparing the two:

CREATE TEMP TABLE pgss_before AS
SELECT * FROM pg_stat_statements;

-- wait long enough for the workload to repeat

CREATE TEMP TABLE pgss_after AS
SELECT * FROM pg_stat_statements;

SELECT
    a.queryid,
    a.calls - b.calls AS calls_delta,
    round((a.total_exec_time - b.total_exec_time)::numeric, 2)
        AS exec_time_delta_ms,
    a.rows - b.rows AS rows_delta,
    a.shared_blks_read - b.shared_blks_read
        AS shared_reads_delta,
    a.temp_blks_written - b.temp_blks_written
        AS temp_written_delta,
    left(a.query, 100) AS query
FROM pgss_after a
JOIN pgss_before b
    ON a.userid = b.userid
    AND a.dbid = b.dbid
    AND a.queryid = b.queryid
WHERE a.calls > b.calls
ORDER BY exec_time_delta_ms DESC
LIMIT 10;

Back in the same database, this time rather than querying pg_stat_activity, I create a first snapshot of what’s happening right now on the system. It’s a temp table of those cumulative values, nothing unique about it. I let it sit, and after about a minute I create the second snapshot.

The diff query takes the deltas of a couple of columns, not all of them. Remember, there are well over 35 or 40 columns and metrics in pg_stat_statements, and I’m not looking for most of them right now. I want to see which queries are being called the most, which have the most total execution time over this period, and things like blocks read and written. Maybe there’s a query writing lots of temporary data, and a high blocks written delta will help me find it.

Ordered by total execution time delta, this shows the queries that took the most time during that minute. A couple of them selected a lot of rows in that minute, and one wrote a lot of temporary data, so there are a lot of pages being written to disk. If I were having a performance problem right now, this is how I’d identify it when I haven’t been tracking history.

The aggressive approach: reset pg_stat_statements and re-query

If you need to dig further, maybe watching a couple of different intervals without taking more and more snapshots, the aggressive approach is one we’ve talked about previously in this series: reset the metrics.

SELECT pg_stat_statements_reset();

This clears out all the metrics and all the queries, and starts you from a fresh table, ready to see what happens. It creates a clean observation interval, which is useful during an active, repeatable, high-volume incident. Avoid it when the problem is rare, or when the existing history matters to you. If you ever want to verify exactly when the metrics were last reset, select from pg_stat_statements_info. It has the deallocation counter we’ve talked about many, many times, and it also tracks the last time the metrics were reset:

SELECT dealloc, stats_reset FROM pg_stat_statements_info;

You can then use a query like the one below, or one of many you’ll find on the internet, to pull the information most relevant to you, using primarily the ORDER BY clause to decide which problematic queries surface first. I also pull out the query ID, the database name, and the role name, which help answer whether this is a one-off, something that runs periodically, or someone’s report that I need to track down:

SELECT
    queryid,
    d.datname,
    r.rolname,
    calls,
    round(total_exec_time::numeric, 2) AS total_exec_ms,
    round(mean_exec_time::numeric, 2) AS mean_exec_ms,
    rows,
    left(query, 120) AS query
FROM pg_stat_statements AS pgss
    JOIN pg_database AS d ON d.oid = pgss.dbid
    JOIN pg_roles AS r ON r.oid = pgss.userid
WHERE dbid = (SELECT oid FROM pg_database WHERE datname = current_database())
ORDER BY total_exec_time DESC
LIMIT 10;

Which pg_stat_statements columns to order by

As a beginning, order by total_exec_time descending. Since the metrics were reset, that tells you which query or queries have taken the most execution time on the server. It’s a first indicator of the ones doing the most work and worth looking at.

But there are other things to identify simply by reordering the same results. Maybe you want to understand which query is running the most, by calls. How is that useful if it’s not taking the most execution time? Or maybe you want to find a query that’s slow every single time it runs, using mean_exec_time. Maybe it’s which queries are reading the most data off disk, or which are writing the most. If you have queries running out of work_mem, they’re writing a lot of temporary information to disk, and those might be the ones to focus on right now because they’re churning data in and out of your cache and onto disk.

Each question is just a different ORDER BY on the same query:

-- What runs the most?
ORDER BY calls DESC

-- What is slow each time it runs?
WHERE calls >= 10
ORDER BY mean_exec_time DESC

-- What reads the most data?
ORDER BY shared_blks_read DESC

-- What spills to temporary storage?
ORDER BY temp_blks_written DESC

The reason this matters, the reason you might order by different metrics, is that it’s not always the slowest query that is your problem. We’ve all heard of death by a thousand cuts. If you have a very fast query that’s called thousands or millions of times over a span of minutes or hours, that query could be taking a lot of execution time in total. If you only look at time per query, you’d say “this query seems much slower than all the others, I’ll focus on that.” But if it only has a few calls in the period, it’s taking a lot less total effort. You need to be able to identify each of those cases as you decide how to sort the results.

Averages alone can hide the biggest opportunity:

Query	Frequency × cost	Total time
A	4 ms × 2,000,000 calls	8,000 seconds
B	4 seconds × 20 calls	80 seconds
Difference	A is individually fast	A consumes 100× more
Decision	Validate with plans and context	Tune where the leverage is real

A demo: finding the queries doing the most work right now

Let’s look at what’s running right now on my server. First I reset the pg_stat_statements metrics, and get the timestamp back. Then I take the query above on the database that’s currently under load, looking at just the columns we discussed, including the query ID, database name, and role name.

Ordered by total execution time, a few queries pop to the top immediately. One has only been called twice in about the last minute, and I can already see it takes about one second to execute. That might be worth looking at.

Next I want to see which queries have been called the most since the reset. Those might be the ones thrashing the server right now. Ordered by calls, I have a query that ran 12 times in the last minute and a half or so. It takes about 270 milliseconds every time it runs. But it’s not returning a lot of rows, it’s not reading anything from disk, and it’s not writing anything to disk, so it’s probably not the one.

Then I want to find out whether I have a query writing a lot of temporary data to disk because it’s out of work_mem, so I order by blocks written. I often find these are the queries that get missed. If you’re not using auto_explain to catch them through their query plans, they can be a real source of churn that you could improve if you knew they existed. In this case, so far, I don’t have any. There is a workload on this server that intentionally creates temporary disk load every so often, it just hasn’t fired in the few minutes since I reset the metrics.

All in all, pg_stat_statements is good all by itself at telling you where to start looking, particularly on active databases where you’re able to do that reset. If you haven’t been tracking metrics over time, and you’re not using a monitoring tool that builds on pg_stat_statements, this is still a good way to hone in on what might be causing your performance issue right now. Once you reset, it might take five or ten minutes, possibly even an hour, of querying the view over and over to see which one jumps out. Maybe a statement only runs two or three times in an hour, but once it finishes you see it’s doing lots of temporary disk writes. That won’t show up if you query once at the minute mark, see nothing, and go troubleshoot a different way.

Why you need a monitoring tool on top of pg_stat_statements

pg_stat_statements with a good monitoring tool really can help you find trends and hotspots. If you’re not yet using a monitoring tool, it’s something you desperately need to investigate. Postgres is very good at providing lots of information, but it can be challenging to use it well without the right tool.

Yes, I work at pganalyze. I think we have a great tool. There are others that are very popular, and if you use them, at least investigate what they offer. It could be Datadog or SolarWinds. There are plenty of open source options in active development that might suit your needs and use tools you already have: pgwatch, PgHero, or pg_statviz, an open source project by a community member.

It’s also possible to roll your own. I’ve done it before, I know lots of people who attempt it, and it can be a valuable learning exercise at the very least. Remember what’s involved: you have to take the snapshots, come up with a history table that tracks what you want, run a process that takes those snapshots over time, retain the samples, and deal with resets. At the very least, choose something and start now.

You know how pg_stat_statements works from watching this series. You know some of the gotchas. You can identify the information it’s tracking. Now it’s time to put it to use to find the queries that need your help, so you can improve and optimize your Postgres database.

The value of a tool is that, aside from finding what’s happening right now, it gives you the information over time. As an example, in the pganalyze application you can see exactly what’s happening and keep that information over days, weeks, and months. You can sort by the same things we’ve talked about, total time or calls per minute, and ask whether a query is churning on your database. Looking at the same database we queried a few minutes ago, you can zoom in on a moment when something was slower for multiple seconds and see which queries were running at that time. Ultimately, that’s where you need to get to with whatever solution you choose.

What to look for in a pg_stat_statements monitoring tool

As you evaluate monitoring tools, there are a couple of things to keep in mind. Not all tools are equal, and some of that is just their background. A tool that monitors many different kinds of databases often can’t go deep on a specific one like Postgres. It might not capture the entire query text, so you get truncated texts. It might query the information too frequently and add lock contention.

We’ve also recognized over time that customers using multiple tools together can see lock contention on pg_stat_statements itself. If you’re on a hosted service like Amazon RDS or Azure, the service provider is very likely querying pg_stat_statements too. So you have the provider doing it, a tool like pganalyze doing it, and if you add another tool on top, you have two, three, or four tools all trying to get the same information, often at different intervals. Those add up and increase the chances of lightweight locks on pg_stat_statements, which becomes another form of lock contention that impacts your application.

A few more questions to ask: are you getting the full query text? How frequently is the tool snapshotting pg_stat_statements? And if you do need to run pg_stat_statements_reset(), will the tool recover gracefully from the reset to zero?

pg_stat_statements is the first step, not the last

Remember that pg_stat_statements is not the last step in your process. It’s essentially the first step, aside from querying pg_stat_activity as I talked about earlier. You use it to prioritize which queries to investigate, looking for trends and for the same query popping up over and over.

From there, use EXPLAIN (ANALYZE, BUFFERS) to understand exactly what’s happening in the execution. Use auto_explain to find slow queries and log the execution plan at the moment they ran, which gives you even better metrics on what’s going on. You might have to use the logs to understand the context of the times when the problematic queries ran. And finally, history is what confirms whether this is something new, a regression of an old query, or whether a fix you made is actually having the intended positive impact. That’s where your monitoring tool really becomes helpful.

Key takeaways

• pg_stat_statements is cumulative, with no timeline. To see change over time you need snapshots, deltas, and history stored outside the view, plus handling for resets, evictions, and new queries.
• During an incident, check pg_stat_activity first. pg_stat_statements only records completed executions, so a long-running query happening right now won’t be in it yet. Look for active sessions with multi-second transaction and query durations.
• Two ways to get a window without history. The safer approach diffs two temp-table snapshots (pgss_before and pgss_after) taken 30 to 60 seconds apart. The aggressive approach runs pg_stat_statements_reset() and re-queries; pg_stat_statements_info tells you when the last reset happened.
• Order by more than total time. total_exec_time finds the biggest total workload, calls finds the query running most often, mean_exec_time finds the query slow on every run, and temp_blks_written finds queries spilling past work_mem. The slowest query is not always your problem.
• Pick a monitoring tool, and check how it treats pg_stat_statements. Ask whether it keeps the full query text, how often it snapshots, whether it survives a reset, and how many other tools (including your hosting provider) are already querying the same view and adding lock contention.
• pg_stat_statements prioritizes; EXPLAIN (ANALYZE, BUFFERS), auto_explain, logs, and history explain. It tells you which queries to investigate, not why they’re slow.

Wrapping up the series

I hope this has been an informative series for you. pg_stat_statements is so integral to the work we do with Postgres that it’s really worth understanding, and now that we’ve been through all of it, I hope you’ve come away with a better ability to use it as an effective tool when you need it to tune and optimize your database.

Thank you so much for watching, and be on the lookout for new things coming on this Postgres in Production series, so that we can help you better understand Postgres and your production workloads.

I hope this series helps you better understand one of the most essential tools in the Postgres ecosystem. Feel free to subscribe to our YouTube channel, sign up for our newsletter or follow us on LinkedIn to get updates about new episodes!

What we discussed

• pg_stat_statements documentation
• The pg_stat_statements_info view and pg_stat_statements_reset()
• The pg_stat_activity view
• auto_explain
• EXPLAIN
• Bluebox sample database
• pgwatch, PgHero, pg_statviz

Other parts in the pg_stat_statements deep dive series

• Part 1: What it is and what it isn’t
• Part 2: What makes a statement unique
• Part 3: Where Your Query Text Actually Lives
• Part 4: How pg_stat_statements Decides What to Keep
• Part 5: Configuring pg_stat_statements to Reduce Deallocations
• Part 6: Diagnosing High Cardinality Workloads