PostgreSQL performance issue investigation with pg_profile

Regardless of your database of choice, it is essential to control resource consumption. Usually, your monitoring system is tracking your DBMS and the server running it. You can obtain information about your CPU, memory, disc utilization, the number of transactions, locks, and a wide variety of other metrics.

However, sooner or later, we will want to know which workload causes the heaviest resource utilization. Are there any statements demanding extra resources to get executed? Does the application run some queries too often? Maybe it requests a lot of data from the database, performing filtration on the application side? We will talk about a simple tool that will help you answer many of such questions with reasonable overhead.

For a Postgres database, there are several approaches available:1.`

• Server log analysis
• Server statistic views analysis

We will talk about the analysis of the statistics views – I mean Postgres Statistics Collector views with pg_stat_statements and pg_stat_kcache extensions. This approach has the following advantages:

• Tracking all queries regardless of a single query execution time without intensive server log generation. Thus we can easily catch frequently called fast queries.
• Tracking database object statistics.
• No need to analyze huge log files.

The disadvantages of this approach are as follows:

• We don’t know the exact parameter values that cause long query execution.
• There is no way to get the exact execution plan of a statement.
• Failed statements are invisible for pg_stat_statements.

pg_profile tool is useful in coarse database workload analysis – when you are investigating the whole database workload profile seeking for the "heaviest" queries and “hot” objects in your database within quite a long time frame. It deals with the increasing statistics provided by Postgres Statistics Collector and extensions.

An increasing statistic is a metric; its value is increasing since the last statistics reset. PostgreSQL provides plenty of such statistics. They are convenient for sampling, and we will get accurate data, regardless of how often we collect samples, and won't lose anything.

Let’s have a look at how pg_profile can help us.

Demo issue – blocks hit rate increased

We will consider a real case of our customer, which is anonymized for NDA compliance. All names are obfuscated and no statements will be shown, but all statistic values are real, and this is all we need for the demonstration.

Below is an elementary example of an issue with pg_stat_database.blks_hit metric. It is an increasing statistic measuring the total amount of blocks got from shared buffers by all sessions since the statistics reset. We can monitor this metric easily. This is what it looks like in our monitoring system:

Figure 1: Read and hit blocks

Figure 1 shows pg_stat_database.blks_hit and pg_stat_database.blks_read rate captured by the monitoring system. Every Postgres monitoring system should have such a chart. There is a two-day long interval where we can see the point when block processing has been raised by several orders of magnitude. It may be normal, or we have just wasted CPU time on the unnecessary page processing. At least, we haven't seen any file system reads here.

If our monitoring system tracks aggregated statistics of pg_stat_statements, the issue can be confirmed in similarly raised execution time metric – pg_stat_statements.total_exec_time.

Figure 2: Block hit rate with execution time

Figure 2 shows the read and hit rate (on the left axis) and the total execution time rate (on the right axis). We know for sure that something has changed in our database workload, and further investigation is needed.

If this issue is in progress right now, we can try to locate the cause of it using OS statistics, pg_stat_activity view, and some other tools based on their data. But when the issue is gone, how can we investigate it?

pg_profile addresses this problem by sampling. While taking a sample, pg_profile collects statistics about queries (obtained from optional extensions pg_stat_statements and pg_stat_kcache), tables, indexes, and user functions. Comparing collected statistics to values observed in the previous sample, pg_profile detects the “top” objects and statements by many different criteria. Statistics for those objects are saved in the pg_profile workload repository.

Taking a sample is not as cheap as typical monitoring queries. Still, there is no need to take them often – one or two samples per an hour is usually sufficient to detect the most significant activities in a database.

Reports

Based on workload repository data, pg_profile can build a report, containing summary workload of most significant database activities during interval between any two samples. This report will contain the following sections about workload during report interval:

• Server statistics – cluster-wide statistics of a postgres instance
• SQL Query statistics – SQL statement lists sorted by various criteria
• Schema object statistics – tables and indexes statistics sorted by various criteria
• User function statistics – user functions execution statistics sorted by time and calls
• Vacuum-related statistics – statistics on tables and indexes influencing vacuum process
• Cluster settings during the report interval – postgresql instance parameters and their changes that were detected in samples

In our case with raised blocks hit rate, we want to know what queries are consumed the most time and fetched pages from shared buffers. pg_profile report, built for time interval between 11:00 and 13:00 should answer this question. Our issue is related to statements execution time and block hit rate, thus corresponding sections will be the first to look at.

Table 1: Top SQL by execution time

The first three statements have consumed over 65% of all execution time in a cluster. Each query ID is a link, and you can click on it to see the actual statement. This article is not about query optimization and we will not focus on exact statements. I just want to show you the easy way to detect the most resource-intensive statements in our database for the specified time interval. Of course, we should see the same statements in the “Top SQL by shared blocks fetched” report table:

Table 2: Top SQL by shared blocks fetched

According to Table 2 displaying top SQL by shared blocks fetched, three leading statements have consumed 91% of all pages fetched in our cluster during the report interval. Also, all of them can be found on the top-5 list of the most time-consuming statements. (I’ve placed a red note with the query time rank in this table for reference). These queries are definitely good candidates for immediate optimization.

What can we say about the relations affected by our issue? Are there any “hot” tables/indexes, or is this issue concerned with many relations? We need to look at the “Top tables by blocks fetched” section of our report.

Table 3: Top tables by blocks fetched

According to this section, almost 54% of all blocks fetched in our cluster were fetched from the table named i6c.i6_n_m. 9% more were received from the second table i6c.i6_d_t_d. Also, 28% of all blocks used by queries in our cluster were fetched from the indexes of our second table.

Summarizing the block fetching load of the top two tables and their indexes, we have 93% of all blocks fetched in our cluster.

And if we want to dive a bit deeper to see the exact indexes under load, we should look at another report table named “Top indexes by blocks fetched”.

Table 4: Top indexes by blocks fetched

Index i6_d_t_d_pk on the table i6c.i6_d_t_d is most likely a primary key index. It is also under the heaviest loaded in our database consuming 28% of all blocks fetched in our cluster.

Differential reports

When you face a sudden performance degradation (as in our case). A differential report is a good starting point for further investigation. This is a report based on two time intervals, providing data for easy statistics comparison. It contains the same sections, but the same objects for different intervals will be located one next to the other.

Let’s see what has been changed since the previous day when the system was working as expected. We will examine a differential report comparing the interval of 11:00-13:00 of the previous day (normal workload) with the interval of 11:00-13:00 of the second day (when the issue was in progress).

First of all, let’s look at the database-level statistics.

Table 5: Database statistics (diff)

In all sections of our differential report, its cells containing information about the first interval will be colored red, while data belonging to the second interval will be colored blue. Significant workload raise is obvious at a database level (pg_stat_database view).

Now, let’s compare the most time-consuming statements' workload.

Table 6: Top SQL by execution time (diff)

Let's have a look at Table 6 displaying top SQL by execution time (diff). Here we are observing the significant statements workload change between the first and the second time interval. Almost all “bad” statements performed much better before the issue occurred – they took noticeably less time for more executions.

Also, now we know one more thing, that could help us further investigate – the most time-consuming query (with ID of 825ec9dfe2) was returning four orders of magnitude more rows during an issue.

Certainly, we want to compare table workload from the point of block fetches. Let’s look at the “Top tables by blocks fetched” table of our differential report.

Table 7: Top tables by blocks fetched (diff)

It looks like a miracle, we can clearly see that top statements before an issue were taking one to four orders of magnitude fewer blocks to complete, we know which tables and indexes were involved and to which extent. Something must have changed drastically in the statement's conditions.

Investigation results

Lies, Damned Lies And Statistics

Of course, statistics could not give us a real cause of performance degradation, it won't show us the execution plans and statements parameters causing bad performance. But statistics collection is relatively cheap, easy to analyze and it can point you in the right direction. It provides you a quantitative assessment of workload change in your database.

Conclusion

pg_profile is an extremely easy-to-use tool for tracking the workload on Postgres databases and getting detailed reports. The main design idea of pg_profile is that you won’t need anything but a Postgres database and a scheduler to use it.

And what about the cause of our investigated issue? We don’t know exactly… Our customer was able to fix it after we provided our findings, based on pg_profile reports!