1

I have just enabled my PostgreSQL 12 instance on Windows 10 to log queries executed by a framework I use. I've changed the following lines in postgresql.conf:

log_destination = 'stderr'
logging_collector = on
log_file_mode = 0640
log_min_duration_statement = 1000
log_duration = on
log_line_prefix = '%m [%p] %q%u@%d (%c) '
log_statement = 'all'

Then restarted the service and executed SELECT pg_reload_conf();

I can see the query being logged, but it is logged multiple times:

2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.013 ms
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di S_4: BEGIN
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.036 ms
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.098 ms
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.170 ms
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:58.955 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:58.965 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.750 ms
2021-04-22 15:16:58.990 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:58.990 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.001 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.423 ms
2021-04-22 15:16:59.028 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.028 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.041 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 13.008 ms
2021-04-22 15:16:59.065 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.065 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.076 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.359 ms
2021-04-22 15:16:59.099 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.099 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.110 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.689 ms
2021-04-22 15:16:59.134 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.134 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.146 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 11.450 ms
2021-04-22 15:16:59.168 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.168 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.178 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.574 ms
2021-04-22 15:16:59.202 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.202 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.211 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.670 ms
2021-04-22 15:16:59.236 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.236 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.245 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 8.417 ms
2021-04-22 15:16:59.271 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.271 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.281 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.099 ms
2021-04-22 15:16:59.306 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.306 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.316 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.002 ms
2021-04-22 15:16:59.341 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.341 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.350 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.362 ms
2021-04-22 15:16:59.374 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.374 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.383 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 8.846 ms
2021-04-22 15:16:59.407 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.407 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.418 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.399 ms
2021-04-22 15:16:59.442 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.442 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.452 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.302 ms
2021-04-22 15:16:59.477 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.477 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.487 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.578 ms
2021-04-22 15:16:59.509 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.509 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.519 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.282 ms
2021-04-22 15:16:59.542 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.542 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.553 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 10.846 ms
2021-04-22 15:16:59.575 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.575 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.588 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 12.898 ms
2021-04-22 15:16:59.612 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.612 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.621 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.128 ms
2021-04-22 15:16:59.643 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.643 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.653 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.380 ms
2021-04-22 15:16:59.676 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.676 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.685 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 8.840 ms
2021-04-22 15:16:59.894 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.894 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.904 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 9.668 ms
2021-04-22 15:16:59.923 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.923 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.942 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 18.108 ms
2021-04-22 15:16:59.961 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di fetch da <unnamed>/C_10: SELECT * FROM table WHERE key=$1 ORDER BY time DESC
2021-04-22 15:16:59.961 CEST [19740] user@db (608173df.4d1c) DETTAGLI:  parametri: $1 = 'key001'
2021-04-22 15:16:59.961 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.086 ms
2021-04-22 15:17:00.195 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.005 ms
2021-04-22 15:17:00.195 CEST [19740] user@db (608173df.4d1c) LOG:  esecuzione di S_1: COMMIT
2021-04-22 15:17:00.195 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.021 ms

Why is that? Is that due to some configuration I made, or PostgreSQL makes it multiple times in different threads, or the framework is actually sending it to PostgreSQL multiple times?

As an aside, how can I avoid logging lines like this one below, which are about queries that take less than log_min_duration_statement?

2021-04-22 15:17:00.195 CEST [19740] user@db (608173df.4d1c) LOG:  durata: 0.005 ms

Thanks, Alessio

Improve this question
2
  • What do you think log_statement = 'all' means? Commented Apr 22, 2021 at 15:46
  • I think it means both ddl and dml statements, subject to other conditions such as log_min_duration_statement Commented Apr 24, 2021 at 14:16

1 Answer 1

Reset to default
1

You notice that there is only one

esecuzione di <unnamed>/C_10

followed by several

esecuzione di fetch da <unnamed>/C_10

So you obviously use a cursor and fetch the result set in pieces. Each of these fetches is a call to the server.

Improve this answer
Sign up to request clarification or add additional context in comments.

Comments

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.