RE: Big performance slowdown from 11.2 to 13.3 - Mailing list pgsql-performance

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

On Thu, Jul 22, 2021 at 04:30:00PM +0000, ldh@laurent-hasson.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=13865785loops=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.598rows=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,"EXUDATEAMOUNT", 
"EXUDATE TYPE","GRANULATION TISSUE","INDICATE OTHER TYPE OF WOUND CLOSURE","INDICATE TYPE","INDICATE WOUND CLOSURE","IS
THISA CLOSED SURGICAL WOUND OR SUSPECTE 
D DEEP TISSUE INJURY?","LENGTH (CM)","MEASUREMENTS TAKEN","NECROTIC TISSUE AMOUNT","NECROTIC TISSUE TYPE",ODOR,"OTHER
COMMENTSREGARDING DEBRIDEMENT TYPE","OTHE 
R COMMENTS REGARDING DRAIN TYPE","OTHER COMMENTS REGARDING PAIN INTERVENTIONS","OTHER COMMENTS REGARDING PAIN
QUALITY","OTHERCOMMENTS REGARDING REASON MEASUREM 
ENTS NOT TAKEN","PAIN FREQUENCY","PAIN INTERVENTIONS","PAIN QUALITY","PERIPHERAL TISSUE EDEMA","PERIPHERAL TISSUE
INDURATION","REASONMEASUREMENTS 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)