Date: Wed, 5 May 2021 01:59:19 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Alex <cdalxndr@yahoo.com>
Cc: pgsql-performance@postgresql.org
Subject: Re: 15x slower PreparedStatement vs raw query
Message-ID: <20210505065919.GQ27406@telsasoft.com>
References: <3f8c88d8a6ef9.d82fa04cf610d.ref@yahoo.com>
 <3f8c88d8a6ef9.d82fa04cf610d@yahoo.com>
 <20210503201811.GA27406@telsasoft.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20210503201811.GA27406@telsasoft.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20210505065919.GQ27406%40telsasoft.com>
Precedence: bulk

On Mon, May 03, 2021 at 03:18:11PM -0500, Justin Pryzby wrote:
> On Sun, May 02, 2021 at 07:45:26PM +0000, Alex wrote:
> > PreparedStatement: 15s
> > Raw query with embedded params: 1s
> > See issue on github with query and explain analyze:
> > https://github.com/pgjdbc/pgjdbc/issues/2145
> 
> | ..PostgreSQL Version?  12
> |Prepared statement
> |...
> |Planning Time: 11.596 ms
> |Execution Time: 14799.266 ms
> |
> |Raw statement
> |Planning Time: 22.685 ms
> |Execution Time: 1012.992 ms
> 
> The prepared statemnt has 2x faster planning time, which is what it's meant to
> improve.
> 
> The execution time is slower, and I think you can improve it with this.
> https://www.postgresql.org/docs/12/runtime-config-query.html#GUC-PLAN-CACHE_MODE

Also, the rowcount estimates are way off starting with the scan nodes.

  ->  Bitmap Heap Scan on category_property_name cpn_limits  (cost=32.13..53.55 rows=14 width=29) (actual time=0.665..8.822 rows=2650 loops=1)
	Recheck Cond: ((lexeme = ANY ('{''rata'',""''polling'' ''rata'' ''ratez''"",""''polling'' ''rata''"",""''rata'' ''ratez'' ''semnal'' ''usb-ul''""}'::tsvector[])) OR (lexeme = '''frecventa'' ''frecventez'''::tsvector) OR (lexeme = '''raportare'' ''rata'' ''ratez'''::tsvector) OR (lexeme = ANY ('{''latime'',""''latime'' ''placi''"",""''compatibila'' ''latime'' ''telefon''""}'::tsvector[])) OR (lexeme = '''lungime'''::tsvector) OR (lexeme = '''cablu'' ''lungime'''::tsvector) OR (lexeme = '''inaltime'''::tsvector) OR (lexeme = '''rezolutie'''::tsvector) OR (lexeme = '''greutate'''::tsvector))
	Heap Blocks: exact=85
	->  BitmapOr  (cost=32.13..32.13 rows=14 width=0) (actual time=0.574..0.577 rows=0 loops=1) 
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..9.17 rows=4 width=0) (actual time=0.088..0.089 rows=10 loops=1)
		    Index Cond: (lexeme = ANY ('{''rata'',""''polling'' ''rata'' ''ratez''"",""''polling'' ''rata''"",""''rata'' ''ratez'' ''semnal'' ''usb-ul''""}'::tsvector[]))
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.047..0.047 rows=171 loops=1) 
		    Index Cond: (lexeme = '''frecventa'' ''frecventez'''::tsvector)                                                                                                                                                              ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.015..0.015 rows=1 loops=1)                                                                                                   Index Cond: (lexeme = '''raportare'' ''rata'' ''ratez'''::tsvector)
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..6.88 rows=3 width=0) (actual time=0.097..0.097 rows=547 loops=1)                                                                                                 Index Cond: (lexeme = ANY ('{''latime'',""''latime'' ''placi''"",""''compatibila'' ''latime'' ''telefon''""}'::tsvector[]))
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.107..0.107 rows=604 loops=1)                                                                                                 Index Cond: (lexeme = '''lungime'''::tsvector)
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.030..0.030 rows=137 loops=1)
		    Index Cond: (lexeme = '''cablu'' ''lungime'''::tsvector)
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.079..0.079 rows=479 loops=1)                                                                                                 Index Cond: (lexeme = '''inaltime'''::tsvector)
	      ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.020..0.020 rows=40 loops=1)
		    Index Cond: (lexeme = '''rezolutie'''::tsvector)                                                                                                                                                                             ->  Bitmap Index Scan on category_property_name_lexeme_idx  (cost=0.00..2.29 rows=1 width=0) (actual time=0.088..0.088 rows=661 loops=1)                                                                                                 Index Cond: (lexeme = '''greutate'''::tsvector)