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>