postgrespro/pg_wait_sampling

queryid is cleared too early with nested queries

shinderuk opened this issue · 2 comments

Here is a demo using two sessions distinguished with indentation:

postgres=# select * from pg_wait_sampling_current where pid = 65936;
  pid  | event_type |   event    | queryid 
-------+------------+------------+---------
 65936 | Client     | ClientRead |       0
(1 row)

		postgres=# create function f(int) returns int as 'select pg_sleep(3); select $1' language sql;
		CREATE FUNCTION
		postgres=# select f(i) from generate_series(1, 3) i;
		...

postgres=# select * from pg_wait_sampling_current where pid = 65936;
  pid  | event_type |  event  |       queryid       
-------+------------+---------+---------------------
 65936 | Timeout    | PgSleep | 8411540322399323155
(1 row)

postgres=# select * from pg_wait_sampling_current where pid = 65936;
  pid  | event_type |  event  | queryid 
-------+------------+---------+---------
 65936 | Timeout    | PgSleep |       0
(1 row)

		 f 
		---
		 1
		 2
		 3
		(3 rows)

postgres=# select * from pg_wait_sampling_current where pid = 65936;
  pid  | event_type |   event    | queryid 
-------+------------+------------+---------
 65936 | Client     | ClientRead |       0
(1 row)

Another example with extra debug output:

postgres=# create function g(int) returns int as 'select 1; select $1 + 1' language sql;
CREATE FUNCTION
postgres=# select i, g(i) from generate_series(1, 3) i;
NOTICE:  planner_hook: set queryid to 4330984749448694052
NOTICE:  planner_hook: queryid is already set to 4330984749448694052 (ignore 15748251446205589984)
NOTICE:  planner_hook: queryid is already set to 4330984749448694052 (ignore 13006084060684650529)
NOTICE:  ExecutorEnd_hook: clear queryid (was 4330984749448694052)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
NOTICE:  ExecutorEnd_hook: clear queryid (was 0)
 i | g 
---+---
 1 | 2
 2 | 3
 3 | 4
(3 rows)

Should pg_wait_sampling track nesting level like pg_stat_statements does?

This issue is consequence that queryId is set for upper-level query but cleared by the first completed subquery.

Should pg_wait_sampling track nesting level like pg_stat_statements does?

Yeah, definitely in perspective. But now it doesn't support nested levels.

Thanks for this buggy case. It's a good augment to the issues around queryId for nested queries described in #43 .

Fixed in v1.1.6