В последнее время я много занимаюсь SQL, поэтому вот еще пара приемов.

Настройка log_duration = on добавляет в лог длительность каждого запроса. Удобно, потому что избавляет от мусорного кода, который перед каждым запросом запоминает текущее время, выполняет его, находит новое время и печатает разницу в консоль. Postgres берет все это на себя:

statement: create table table8855 (id integer)
duration: 11.607 ms
statement: BEGIN
duration: 0.046 ms
statement: insert into table8855 values (1), (2)
duration: 0.368 ms
statement: ROLLBACK
duration: 0.052 ms
statement: select * from table8855
duration: 0.414 ms

Вторая настройка log_line_prefix отвечает за информацию, которая показана в логе перед запросом. По умолчанию это время с точностью до миллисекунд и номер процесса:

2023-06-02 14:45:52.395 MSK [57002] LOG:  statement: BEGIN

Я предпочитаю вот что:

log_line_prefix = '%t [%v]'

  • %t выводит время без миллисекунд, что короче;

  • %v означает виртуальный номер транзакции. Виртуальный потому, что до ее завершения система не знает, какой номер будет в итоге. Поэтому выводится пара [tmin/tmax] — диапазон транзакций, доступный запросу в текущий момент.

Зачем это нужно? Бывают баги, когда разработчик ошибается с транзакциями, например открывает ее, но шлет запросы через старое соединение. Если что-то упадет в процессе, изменения будут частичными, что выливается проблемы на проде.

С логами ниже легко понять, кто на ком стоял. Запросы с меткой [3/5] относятся к одной транзакции, а [4/2] — к другой.

[3/4]LOG: create table table8856 (id integer)
[3/5]LOG: BEGIN
[3/5]LOG: SET TRANSACTION ISOLATION LEVEL SERIALIZABLE
[3/5]LOG: insert into table8856 values (1), (2)
[3/5]LOG: select * from table8856
[4/2]LOG: select * from table8856
[3/5]LOG: COMMIT

Заодно можно посчитать, сколько было транзакций, насколько они пересекаются и, возможно, разнести их по времени.