RE: Big performance slowdown from 11.2 to 13.3

-----Original Message-----
From: Justin Pryzby <pryzby(at)telsasoft(dot)com>
Sent: Thursday, July 22, 2021 12:36
To: ldh(at)laurent-hasson(dot)com
Cc: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>; David Rowley <dgrowleyml(at)gmail(dot)com>; Peter Geoghegan <pg(at)bowt(dot)ie>; pgsql-performance(at)postgresql(dot)org
Subject: Re: Big performance slowdown from 11.2 to 13.3

On Thu, Jul 22, 2021 at 04:30:00PM +0000, ldh(at)laurent-hasson(dot)com wrote:
> Hello Justin,
>
> > log_executor_stats=on; client_min_messages=debug;
>
> Would the results then come in EXPLAIN or would I need to pick something up from the logs?

If you're running with psql, and client_min_messages=debug, then it'll show up as a debug message to the client:

ts=# SET log_executor_stats=on; SET client_min_messages=debug; explain analyze SELECT 1; SET SET
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.000011 s user, 0.000209 s system, 0.000219 s elapsed
! [0.040608 s user, 0.020304 s system total]
! 7808 kB max resident size
...

It can but doesn't have to use "explain" - that just avoids showing the query output, since it's not what's interesting here.

--
Justin

-------------------------------------------------------------------------------------

Justin,

I tried this but not seeing max resident size data output.

Pepper=# SET log_executor_stats=on; SET client_min_messages=debug; explain analyze SELECT 1;
SET
SET
LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 0.000000 s user, 0.000000 s system, 0.000109 s elapsed
! [494.640625 s user, 19.171875 s system total]
QUERY PLAN
------------------------------------------------------------------------------------
Result (cost=0.00..0.01 rows=1 width=4) (actual time=0.002..0.002 rows=1 loops=1)
Planning Time: 0.041 ms
Execution Time: 0.012 ms
(3 rows)

For my query:

LOG: EXECUTOR STATISTICS
DETAIL: ! system usage stats:
! 169.625000 s user, 5.843750 s system, 175.490088 s elapsed
! [494.640625 s user, 19.171875 s system total]
HashAggregate (cost=1764285.18..1764296.18 rows=200 width=1260) (actual time=86323.813..174737.442 rows=723659 loops=1)
Group Key: t.iccqa_iccassmt_fk
Buffers: shared hit=364 read=170293, temp written=83229
CTE t
-> HashAggregate (cost=1343178.39..1356985.17 rows=1380678 width=56) (actual time=22594.053..32519.573 rows=13865785 loops=1)
Group Key: assessmenticcqa_raw.iccqar_iccassmt_fk, assessmenticcqa_raw.iccqar_ques_code
Buffers: shared hit=364 read=170293
-> Seq Scan on assessmenticcqa_raw (cost=0.00..1240682.76 rows=13666084 width=38) (actual time=0.170..10714.598 rows=13865785 loops=1)
Filter: ((iccqar_ques_code)::text = ANY ('{"DEBRIDEMENT DATE","DEBRIDEMENT THIS VISIT","DEBRIDEMENT TYPE","DEPTH (CM)","DEPTH DESCRIPTION","DOE
S PATIENT HAVE PAIN ASSOCIATED WITH THIS WOUND?","DRAIN PRESENT","DRAIN TYPE","EDGE / SURROUNDING TISSUE - MACERATION",EDGES,EPITHELIALIZATION,"EXUDATE AMOUNT",
"EXUDATE TYPE","GRANULATION TISSUE","INDICATE OTHER TYPE OF WOUND CLOSURE","INDICATE TYPE","INDICATE WOUND CLOSURE","IS THIS A CLOSED SURGICAL WOUND OR SUSPECTE
D DEEP TISSUE INJURY?","LENGTH (CM)","MEASUREMENTS TAKEN","NECROTIC TISSUE AMOUNT","NECROTIC TISSUE TYPE",ODOR,"OTHER COMMENTS REGARDING DEBRIDEMENT TYPE","OTHE
R COMMENTS REGARDING DRAIN TYPE","OTHER COMMENTS REGARDING PAIN INTERVENTIONS","OTHER COMMENTS REGARDING PAIN QUALITY","OTHER COMMENTS REGARDING REASON MEASUREM
ENTS NOT TAKEN","PAIN FREQUENCY","PAIN INTERVENTIONS","PAIN QUALITY","PERIPHERAL TISSUE EDEMA","PERIPHERAL TISSUE INDURATION","REASON MEASUREMENTS NOT TAKEN","R
ESPONSE TO PAIN INTERVENTIONS",SHAPE,"SIGNS AND SYMPTOMS OF INFECTION","SKIN COLOR SURROUNDING WOUND",STATE,"SURFACE AREA (SQ CM)","TOTAL NECROTIC TISSUE ESCHAR
","TOTAL NECROTIC TISSUE SLOUGH",TUNNELING,"TUNNELING SIZE(CM)/LOCATION - 12 - 3 O''CLOCK","TUNNELING SIZE(CM)/LOCATION - 3 - 6 O''CLOCK","TUNNELING SIZE(CM)/LO
CATION - 6 - 9 O''CLOCK","TUNNELING SIZE(CM)/LOCATION - 9 - 12 O''CLOCK",UNDERMINING,"UNDERMINING SIZE(CM)/LOCATION - 12 - 3 O''CLOCK","UNDERMINING SIZE(CM)/LOC
ATION - 3 - 6 O''CLOCK","UNDERMINING SIZE(CM)/LOCATION - 6 - 9 O''CLOCK","UNDERMINING SIZE(CM)/LOCATION - 9 - 12 O''CLOCK","WIDTH (CM)","WOUND PAIN LEVEL, WHERE
0 = \"NO PAIN\" AND 10 = \"WORST POSSIBLE PAIN\""}'::text[]))
Rows Removed by Filter: 172390
Buffers: shared hit=364 read=170293
-> CTE Scan on t (cost=0.00..27613.56 rows=1380678 width=552) (actual time=22594.062..40248.874 rows=13865785 loops=1)
Buffers: shared hit=364 read=170293, temp written=83229
Planning Time: 0.728 ms
Execution Time: 175482.904 ms
(15 rows)