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 <mich...@paquier.xyz> wrote:
> 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
>
