Performance bug in prepared statement binding in 9.2?

Folks,

I'm seeing what may be a major performance bug in BIND in 9.2.4.

We have a client who has an application which uses
Tomcat+Hibernate+JDBC.  They are in the process of upgrading this
application from 8.4.17 to 9.2.4.  As part of this, they have been doing
performance testing, and 9.2 is coming out MUCH worse than 8.4.  The
problem appears to be bind/plan time.

Their application does not use prepared queries usefully, doing
parse,bind,execute on every query cycle.

Here's timings overall for 29 test cycles (cycle 1 has been omitted).
As you can see, parse+execute times are pretty much constant, as are
application think times, but bind times vary quite a lot.  In 8.4, the
29 cycles are constantly 4.5min to 5.75min long.  In 9.2, which is the
chart below, they are all over the place.

Definitions:
cycle: test cycle #, arbitrary.  Each cycle does the same amount of
"work" measured in rows of data.
non_bind_time: time spent in PARSE and EXECUTE.
bind_time: time spent in BIND
app_time: time spent outside Postgres
all times are in minutes:

 cycle | non_bind_time | bind_time | app_time | total_time
-------+---------------+-----------+----------+------------
     2 |          0.79 |      0.62 |     3.19 |       4.60
     3 |          0.77 |      0.87 |     3.13 |       4.77
     4 |          0.76 |      1.10 |     3.16 |       5.02
     5 |          0.76 |      1.26 |     3.08 |       5.10
     6 |          0.72 |      1.40 |     3.08 |       5.20
     7 |          0.72 |      1.51 |     3.05 |       5.28
     8 |          0.70 |      1.60 |     3.07 |       5.37
     9 |          0.73 |      1.72 |     3.05 |       5.50
    10 |          0.71 |      1.84 |     3.05 |       5.60
    11 |          0.70 |      1.96 |     3.07 |       5.73
    12 |          0.74 |      2.11 |     3.08 |       5.93
    13 |          0.74 |      3.58 |     3.08 |       7.40
    14 |          0.73 |      2.41 |     3.08 |       6.22
    15 |          0.75 |      4.15 |     3.08 |       7.98
    16 |          0.74 |      2.69 |     3.09 |       6.52
    17 |          0.76 |      4.68 |     3.09 |       8.53
    18 |          0.74 |      2.99 |     3.09 |       6.82
    19 |          0.77 |      5.24 |     3.11 |       9.12
    20 |          0.75 |      3.29 |     3.08 |       7.12
    21 |          0.78 |      5.90 |     3.14 |       9.82
    22 |          0.78 |      3.57 |     3.12 |       7.47
    23 |          0.76 |      6.17 |     3.10 |      10.03
    24 |          0.77 |      6.61 |     3.10 |      10.48
    25 |          0.77 |      3.97 |     3.11 |       7.85
    26 |          0.77 |      5.24 |     3.12 |       9.13
    27 |          0.76 |      7.15 |     3.12 |      11.03
    28 |          0.76 |      4.37 |     3.10 |       8.23
    29 |          0.78 |      4.48 |     3.12 |       8.38
    30 |          0.76 |      7.73 |     3.11 |      11.60

I pulled out some of the queries with the greatest variance in bind
time.  Unexpectedly, they are not particularly complex.  Here's the
anonymized plan for a query which in the logs took 80ms to bind:

http://explain.depesz.com/s/YSj

Nested Loop  (cost=8.280..26.740 rows=1 width=289)
  ->  Nested Loop  (cost=8.280..18.450 rows=1 width=248)
        ->  Hash Join  (cost=8.280..10.170 rows=1 width=140)
                Hash Cond: (foxtrot2kilo_oscar.quebec_seven =
kilo_juliet1kilo_oscar.sierra_quebec)
              ->  Seq Scan on foxtrot november  (cost=0.000..1.640
rows=64 width=25)
              ->  Hash  (cost=8.270..8.270 rows=1 width=115)
                    ->  Index Scan using quebec_six on victor_india
sierra_oscar  (cost=0.000..8.270 rows=1 width=115)
                            Index Cond: (quebec_seven = 10079::bigint)
        ->  Index Scan using alpha on seven_tango lima
(cost=0.000..8.270 rows=1 width=108)
                Index Cond: ((xray = 10079::bigint) AND (golf =
10002::bigint))
  ->  Index Scan using six on india victor_romeo  (cost=0.000..8.280
rows=1 width=41)
          Index Cond: (quebec_seven = seven_victor0kilo_oscar.delta)

As you can see, it's not particularly complex; it only joins 4 tables,
and it has 2 parameters.  This database does have some horrible ugly
queries with up to 500 parameters, but inexplicably those don't take a
particularly long time to bind.

Note that I have not been able to reproduce this long bind time
interactively, but it's 100% reproducable in the test.

--
Josh Berkus
PostgreSQL Experts Inc.
http://pgexperts.com