The same query_id for different queries

On Tue, Jul 01, 2025 at 10:24:14AM +0300, Maksim Gorkov wrote:

2064869707185898531;'BEGIN;...' -- the full text in query1.sql attachment
2064869707185898531;'COMMIT;'

there is another example, if required I can send it for review.

Why does this happen and how can it be fixed?

Hard to say based on the information you are giving here. First, what
you are posting is not a self-contained case. It sounds to me that
you may be seeing two entries with one for a top-level query and one
for a non-top-level query. In this case the same query ID could be
used.
--
Michael

A few more examples:
1. Why are different query_ids displayed in the log for this test query?
2025-07-01 13:38:47.852 MSK [2518006:549/405366] [postgres] pgAdmin
*-11391618518959119* 10.206.112.24(51180) LOG: duration: 101.141 ms plan:
Query Text: BEGIN;
select pg_sleep(.1);
COMMIT;

Result (cost=0.00..0.01 rows=1 width=4) (actual
time=101.130..101.131 rows=1 loops=1)
2025-07-01 13:38:47.852 MSK [2518006:549/0] [postgres] pgAdmin
*2064869707185898531* 10.206.112.24(51180) LOG: duration: 101.322 ms
statement: BEGIN;
select pg_sleep(.1);
COMMIT;

2. The first two lines in the log show the query_id equal to 0, but in the
last line the query_id is different and it is the same as in the previous
example:
2025-07-01 00:01:28.625 MSK [1931448:19/12331582] [dbname1] *0* [local]
apname1 LOG: duration: 55.881 ms execute <unnamed>:
WITH progress AS MATERIALIZED (
SELECT
unnest[1]::integer event_id,
unnest[2]::date period_date,
unnest[3]::integer account,
unnest[4]::date planned_date
FROM (
SELECT unnest($1::text[])::text[]
) AS F
)
SELECT *
FROM "SummaryState"
INNER JOIN progress ON(
"Event" = "event_id"
AND "PeriodDate" = "period_date"
AND "DateTime" = "planned_date"
AND "Account" = "account"
)
WHERE "DateTime" = ANY($2)

2025-07-01 00:01:28.625 MSK [1931448:19/12331582] [dbname1] *0* [local]
apname1 DETAIL: parameters: $1 = '{ "{ 9714705, ''2024-12-31'', 20751406,
''2025-0>
2025-07-01 00:01:28.627 MSK [1931448:19/12331582] [dbname1]
*2064869707185898531* [local] apname1 LOG: duration: 55.874 ms plan:
Query Text:
WITH progress AS MATERIALIZED (
SELECT
unnest[1]::integer event_id,
unnest[2]::date period_date,
unnest[3]::integer account,
unnest[4]::date planned_date
FROM (
SELECT unnest($1::text[])::text[]
) AS F
)
SELECT *
FROM "SummaryState"
INNER JOIN progress ON(
"Event" = "event_id"
AND "PeriodDate" = "period_date"
AND "DateTime" = "planned_date"
AND "Account" = "account"
)
WHERE "DateTime" = ANY($2)

Query Parameters: $1 = '{ "{ 9714705, ''2024-12-31'', 20751406,
''2025-03-25'' }","{ 9714705, ''2023-12-31'', 20751406, ''2024-03-25''
}","{ 9714706, ''2025-06-30'', 20751406, ''2025-07-25'' }","{ 97147>
Nested Loop (cost=4.74..5235.80 rows=13 width=312) (actual
time=1.477..55.146 rows=86 loops=1)
Buffers: shared hit=303 read=93
I/O Timings: shared read=51.064
CTE progress
-> Subquery Scan on f (cost=0.00..4.20 rows=88 width=16)
(actual time=0.080..0.578 rows=88 loops=1)
-> Result (cost=0.00..2.44 rows=88 width=32) (actual
time=0.053..0.303 rows=88 loops=1)
-> ProjectSet (cost=0.00..0.46 rows=88 width=32)
(actual time=0.049..0.098 rows=88 loops=1)
-> Result (cost=0.00..0.01 rows=1 width=0)
(actual time=0.001..0.002 rows=1 loops=1)
-> CTE Scan on progress (cost=0.00..1.76 rows=88 width=16)
(actual time=0.085..0.670 rows=88 loops=1)
-> Append (cost=0.54..59.22 rows=21 width=295) (actual
time=0.613..0.615 rows=1 loops=88)
<skipped>

On Tue, Jul 1, 2025 at 11:16 AM Michael Paquier <michael@paquier.xyz> wrote: