Temporary file summary and repeated queries in the same session

[blogh]

I noticed that the temporary file summary is sometimes misleading with queries that are repeated several times in the same session.

For example, this :

-- log_line_prefix =  '%t [%p]: [%l-1] db=%d,user=%u,app=%a,client=%h '
SET log_temp_files TO 0;
SET work_mem = 64;
\o /dev/null
SELECT * FROM pg_class ORDER BY 3; -- tempfile size : 81920
SELECT * FROM pg_class ORDER BY 3;
SELECT * FROM pg_class ORDER BY 3;
SELECT * FROM pg_class ORDER BY 3;
SELECT * FROM pg_class ORDER BY 3;

Will generate a report with one query who has created "400.00 KiB" of temp files.

pgbadger --disable-type \
         --disable-session \
         --disable-connection \
         --disable-lock \
         --disable-checkpoint \
         --disable-autovacuum \
         --prefix "%t [%p]: [%l-1] db=%d,user=%u,app=%a,client=%h " \
         -o ~/tmp/postgresql-Tue.txt ~/tmp/postgresql-Tue.log

- Overall statistics ---------------------------------------------------

Number of unique normalized queries: 1
Number of queries: 0
Total query duration: 0ms
First query: -
Last query: -
Query peak: 0 queries/s at 2021-10-05 14:34:04
Number of events: 1
Number of unique normalized events: 1
Number temporary files: 5
Max size of temporary files: 400.00 KiB
Average size of temporary files: 80.00 KiB

- Queries generating the most temporary files (N) ---------------------------

Rank   Count   Total size    Min/Max/Avg size    Query
1)   1 - 409,600 - 409,600/409,600/409,600.00 - select * from pg_class order by ?;
--
        - Example 1: 0ms - 2021-10-05 14:34:04 - database: postgres, user: postgres, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;

- Queries generating the largest temporary files ----------------------------

Rank   Size    Query
1)   409,600 - 2021-10-05 14:34:04 - database: postgres, user: postgres, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;

The current calculus seem to add together:

• different segments of the same temp file +
• different tempfiles of the same query +
• the tempfiles of the same queries executed several times in the same session.

[darold]

You should upgrade your pgbager installation, with latest the same reports:

- Queries generating the most temporary files (N) ---------------------------

Rank   Count   Total size    Min/Max/Avg size    Query
1)   5 - 450,560 - 90,112/90,112/90,112.00 - select * from pg_class order by ?;
--
        - Example 1: 7ms - 2021-10-05 16:58:54 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
        - Example 2: 5ms - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
        - Example 3: 3ms - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;

- Queries generating the largest temporary files ----------------------------

Rank   Size    Query
1)   90,112 - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
2)   90,112 - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
3)   90,112 - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
4)   90,112 - 2021-10-05 16:58:53 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;
5)   90,112 - 2021-10-05 16:58:54 - database: gilles, user: gilles, remote: [local], app: psql - SELECT * FROM pg_class ORDER BY 3;

[blogh]

I don't understand, I am using v11.6.

Is it what you get with this log file ?

2021-10-05 14:33:36 CEST [507807]: [3-1] db=,user=,app=,client= LOG:  starting PostgreSQL 13.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 10.3.1 20210422 (Red Hat 10.3.1-1), 64-bit
2021-10-05 14:33:36 CEST [507807]: [4-1] db=,user=,app=,client= LOG:  listening on IPv6 address "::1", port 5433
2021-10-05 14:33:36 CEST [507807]: [5-1] db=,user=,app=,client= LOG:  listening on IPv4 address "127.0.0.1", port 5433
2021-10-05 14:33:36 CEST [507807]: [6-1] db=,user=,app=,client= LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5433"
2021-10-05 14:33:36 CEST [507807]: [7-1] db=,user=,app=,client= LOG:  listening on Unix socket "/tmp/.s.PGSQL.5433"
2021-10-05 14:33:36 CEST [507812]: [1-1] db=,user=,app=,client= LOG:  database system was shut down at 2021-10-05 14:33:35 CEST
2021-10-05 14:33:36 CEST [507807]: [8-1] db=,user=,app=,client= LOG:  database system is ready to accept connections
2021-10-05 14:34:04 CEST [507833]: [1-1] db=postgres,user=postgres,app=psql,client=[local] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp507833.0", size 81920
2021-10-05 14:34:04 CEST [507833]: [2-1] db=postgres,user=postgres,app=psql,client=[local] STATEMENT:  SELECT * FROM pg_class ORDER BY 3;
2021-10-05 14:34:05 CEST [507833]: [3-1] db=postgres,user=postgres,app=psql,client=[local] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp507833.1", size 81920
2021-10-05 14:34:05 CEST [507833]: [4-1] db=postgres,user=postgres,app=psql,client=[local] STATEMENT:  SELECT * FROM pg_class ORDER BY 3;
2021-10-05 14:34:06 CEST [507833]: [5-1] db=postgres,user=postgres,app=psql,client=[local] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp507833.2", size 81920
2021-10-05 14:34:06 CEST [507833]: [6-1] db=postgres,user=postgres,app=psql,client=[local] STATEMENT:  SELECT * FROM pg_class ORDER BY 3;
2021-10-05 14:34:07 CEST [507833]: [7-1] db=postgres,user=postgres,app=psql,client=[local] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp507833.3", size 81920
2021-10-05 14:34:07 CEST [507833]: [8-1] db=postgres,user=postgres,app=psql,client=[local] STATEMENT:  SELECT * FROM pg_class ORDER BY 3;
2021-10-05 14:34:10 CEST [507833]: [9-1] db=postgres,user=postgres,app=psql,client=[local] LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp507833.4", size 81920
2021-10-05 14:34:10 CEST [507833]: [10-1] db=postgres,user=postgres,app=psql,client=[local] STATEMENT:  SELECT * FROM pg_class ORDER BY 3;

[darold]

Not exactly I have the log_min_duration_statement set to 0.

[darold]

I'm able to reproduce with log_min_duration_statement = -1. I will see if I can handle this case.

[darold]

Commit a10d1df fixes this issue.

[blogh]

thanks !