pg_sampletolog: An extension to log a sample of statements
This article will introduce you to an extension that I developed in order to log a sample of statements.
When a DBA is faced with a performance problem, he will inspect
logs, but also the
An expensive query will appear in
pg_stat_stat_statements and in the logs if
the query exceeds
log_min_duration_statement. Thus, the DBA can replay the query,
and obtains its execution plan to investigate.
To go even further, it is possible to enable the
This way we will have the plan of the query directly. For information, the option
auto_explain.log_analyze does not imply a double execution of the query.
This parameter can be activated without fear. However, this can be costly because
postgres must activate per node instrumentation to obtain timings. If we have a
high throughput, it is also possible to sample with
This option can produce a large quantity of logs which can be problematic on
an instance with high throughput.
I was faced with a very simple problem: how to investigate a request with a
very short execution time? It’s very simple “Look at
Here is what you could get on a pgbench test:
query | SELECT abalance FROM pgbench_accounts WHERE aid = $1 calls | 12000 total_time | 214.564185000001 min_time | 0.013751 max_time | 0.044711 mean_time | 0.0178803487499999
The query is standardized. Without parameter it is impossible to get your plan. Choosing a random parameter is not the right solution: it is not necessarily representative of the real production traffic.
A few months ago, I proposed a patch to log a sample of queries. This one has been integrated in version 12 still under development:
commit 88bdbd3f746049834ae3cc972e6e650586ec3c9d Author: Alvaro Herrera <firstname.lastname@example.org> AuthorDate: Thu Nov 29 18:42:53 2018 -0300 Commit: Alvaro Herrera <email@example.com> CommitDate: Thu Nov 29 18:42:53 2018 -0300 Add log_statement_sample_rate parameter This allows to set a lower log_min_duration_statement value without incurring excessive log traffic (which reduces performance). This can be useful to analyze workloads with lots of short queries. Author: Adrien Nayrat Reviewed-by: David Rowley, Vik Fearing Discussion: https://firstname.lastname@example.org
In the thread, Nikolay Samokhvalov put forward the idea of having the same type functionality but at the transaction level: https://www.postgresql.org/message-id/CANNMO%2BLg65EFqHb%2BZYbMLKyE2y498HJzsdFrMnW1dQ6AFJ3Mpw%40mail.gmail.com
I also proposed a patch to this purpose: Log a sample of transactions
All this stuff is interesting, but you’ll have to wait until version 12, and there’s no guarantee that the second patch will be committed (or that the first one will not be reverted).
All this gave me the idea and the desire to create an extension, that’s how pg_sampletolog was born.
pg_sampletolog allows to:
- Log a sample of statements
- Log a sample of transactions
- Log before or after execution (in order to be compatible with pgreplay)
- Log all
MODstatements, same as log_statement
It should works on all supported version from 9.4 to 11.
pg_sampletolog must me loaded either:
- In local session with
session_preload_libraries. To be loaded at connection start.
New settings should be visible in
select name from pg_settings where name like 'pg_sampletolog%'; name ---------------------------------------- pg_sampletolog.disable_log_duration pg_sampletolog.log_before_execution pg_sampletolog.log_level pg_sampletolog.log_statement pg_sampletolog.statement_sample_rate pg_sampletolog.transaction_sample_rate (6 rows)
Here are a few examples:
- Log only 10% of statements:
pg_sampletolog.statement_sample_rate = 0.1
pg_sampelog will log 10% of requests. For each statements, postgres will make a
random selection using
random() function. The cost of this function is very low,
so there should be no impact on performance.
After a few requests you should get this kind of message in the logs :
2019-01-27 12:50:39.361 CET  LOG: Sampled query duration: 0.014 ms - SELECT 1;
pg_sampelog will log the statement and its execution time.
- Log only 10 of transactions:
pg_sampletolog.transaction_sample_rate = 0.1
The operation is the same as before, with the difference that postgres will choose whether or not to log all statements for the same transaction. This can be very useful in understanding what an application does. For example, when application code is not accessibled or when statements are generated by an ORM.
Example with a simple transaction:
BEGIN; SELECT 1; SELECT 1; COMMIT;
2019-01-27 12:51:40.562 CET  LOG: Sampled transaction duration: 0.008 ms - SELECT 1; 2019-01-27 12:51:40.562 CET  LOG: Sampled transaction duration: 0.005 ms - SELECT 1;
Both SELECTs have been successfully logged. By changing
can see that it is the same transaction (look at the lxid):
2019-01-27 16:32:16 CET : lxid=3/177,db=postgres,user=anayrat LOG: Sampled transaction - SELECT 1; 2019-01-27 16:32:16 CET : lxid=3/177,db=postgres,user=anayrat LOG: Sampled transaction - SELECT 1;
- Log all DDL statements:
pg_sampletolog.log_statement = 'ddl':
pg_sampletolog will log all DDL orders (
This can be useful if you just want to log a read sample but all DDL orders.
2019-01-27 12:53:47.564 CET  LOG: Sampled ddl CREATE TABLE t1(c1 int);
- Log all data-modifying statements:
pg_sampletolog.log_statement = 'mod':
Exactly like the previous example, but this time we also log all the
This includes DDL orders.
2019-01-27 12:59:54.043 CET  LOG: Sampled query duration: 0.246 ms - INSERT INTO t1 VALUES(1); 2019-01-27 13:00:16.468 CET  LOG: Sampled ddl CREATE INDEX ON t1(c1);
- Log before execution:
pg_sampletolog.log_before_execution = on
This option could be useful to replay logs with pgreplay.
The extension also works on standby servers.
pg_stat_stat_statements is enabled, the queryid is also logged. This can be
very useful if you identify a query in
pg_stat_stat_statements and want to find
it in the logs by using its queryid.
I enjoyed this personal project. I learned a lot about
code and it also shows how postgres is extensible.
In the future I would like to add the possibility to log a sample statement corresponding to such queryid. I also have to look to support prepared statements.
Finally, I would like to test this extension with pgreplay: By logging all MOD orders (to ensure consistency during replay) as well as a fraction of the read queries. Then, restore a PITR backup and on the one hand replay writes. On the other hand, replay a portion of reads with a speed_factor. For example x10 by replaying 10% of the traffic. Even if it will never be perfect (it will lack reads consistency), I will be curious to see the results that we can get. Especially if logging all statements would be too expensive.
I’m interested in any feedback to make on the github of the project.