Thread: difference on execution time between prepared statement in pgAdmin and through JDBC Stack

Hello everyone,

i am puzzled like many other users of this list before. I read a lot of
old threads today, but nothing seemed to explain what i see in my log files.

I am using Postgres 9 on linux and the appropriate JDBC driver for this
database. I can also see the same behaviour on production system running
postgres 8.4.

My query:

prepare t1 (int4, int4) AS
  SELECT DISTINCT vec.*, s.statistic_difficulty as examination_difficulty,
  s.statistic_discriminatorypower as examination_discriminatorypower,
  vimc.mediacount,vis.difficulty, vis.discriminatorypower,
vis.statistic_counter, virc.reviewcount, u.user_surname
  FROM ims_vexaminationcontent vec
  LEFT OUTER JOIN ims_statistic s ON vec.item_id = s.object_id AND
s.examination_id = vec.examination_id
  LEFT OUTER JOIN ims_vitemmediacount vimc ON (vimc.item_id = vec.item_id)
  LEFT OUTER JOIN ims_vitemstatistic vis ON (vis.item_id = vec.item_id)
  INNER JOIN ims_user u on (author_id = u.user_id)
  LEFT OUTER JOIN ims_vitemreviewcount virc ON virc.item_id = vec.item_id
  WHERE ((vec.examinationcontentversion_version=1 AND
vec.examination_entityid=7429))
  ORDER BY vec.examinationcontentversion_sequenceno ASC NULLS LAST

and following execute t1 (1,7429); runs in approx. 100 ms.

If a run the same query through my web application (using the same
parameters) my server log file tells me the statement takes approx.
1100ms. This is factor 10!

duration: 1151.088 ms  execute <unnamed>: SELECT DISTINCT vec.*,
s.statistic_difficulty as examination_difficulty,
s.statistic_discriminatorypower as examination_discriminatorypower,
vimc.mediacount,vis.difficulty, vis.discriminatorypower,
vis.statistic_counter, virc.reviewcount, u.user_surname FROM
ims_vexaminationcontent vec LEFT OUTER JOIN ims_statistic s ON
vec.item_id = s.object_id AND s.examination_id = vec.examination_id LEFT
OUTER JOIN ims_vitemmediacount vimc ON (vimc.item_id = vec.item_id) LEFT
OUTER JOIN ims_vitemstatistic vis ON (vis.item_id = vec.item_id) INNER
JOIN ims_user u on (author_id = u.user_id) LEFT OUTER JOIN
ims_vitemreviewcount virc ON virc.item_id = vec.item_id WHERE
((vec.examinationcontentversion_version=$1 AND
vec.examination_entityid=$2)) ORDER BY
vec.examinationcontentversion_sequenceno ASC NULLS LAST LIMIT
2011-02-24 15:22:16 CET DETAIL:  parameters: $1 = '1', $2 = '7429'

As you can see the application uses unnamed prepared statements which i
learnt today executes query planning everytime the statement runs and
after the variables are bound.

So i don't understand the difference between running the query through
the jdbc stack.

Thank you for any helpful link or explanation in advance.

Lars

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Lars Feistner

Kompetenzzentrum für Prüfungen in der Medizin
Medizinische Fakultät Heidelberg,
Im Neuenheimer Feld 346, Raum 013
69120 Heidelberg

E-Mail: feistner@uni-heidelberg.de
Fon:   +49-6221-56-8269
Fax:   +49-6221-56-7175

WWW:   http://www.ims-m.de
        http://www.kompmed.de
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

A named prepared statement (which you seem to be using through
pgAdmin) is *not* the same thing as a PreparedStatement in JDBC. Most
pertinently, JDBC is using an unnamed portal to execute the query,
which delays planning until the parameters are provided. I don't think
this ever happens with a named prepared statement (it would help if
you provided server-side logs for the pgAdmin execution as well). The
deferred planning behavior typically works to your advantage, but you
may have run into some edge case here.

Alternately, because the unnamed portal execution actually also does
the planning, I presume it's counted in the time of the statement
execution, whereas in the pgAdmin case, it looks like you're only
timing the execute, which is going against an already-planned (at
prepare time) query, so you may be comparing apples to oranges.

---
Maciek Sakrejda | System Architect | Truviso

1065 E. Hillsdale Blvd., Suite 215
Foster City, CA 94404
(650) 242-3500 Main
www.truviso.com

Using copy and paste you should be able to time both using explain
analyze to get real timings and the decision tree.

in psql issue the following command

explain analyze select ....

Dave

On Thu, Feb 24, 2011 at 1:38 PM, Maciek Sakrejda <msakrejda@truviso.com> wrote:
> A named prepared statement (which you seem to be using through
> pgAdmin) is *not* the same thing as a PreparedStatement in JDBC. Most
> pertinently, JDBC is using an unnamed portal to execute the query,
> which delays planning until the parameters are provided. I don't think
> this ever happens with a named prepared statement (it would help if
> you provided server-side logs for the pgAdmin execution as well). The
> deferred planning behavior typically works to your advantage, but you
> may have run into some edge case here.
>
> Alternately, because the unnamed portal execution actually also does
> the planning, I presume it's counted in the time of the statement
> execution, whereas in the pgAdmin case, it looks like you're only
> timing the execute, which is going against an already-planned (at
> prepare time) query, so you may be comparing apples to oranges.
>
> ---
> Maciek Sakrejda | System Architect | Truviso
>
> 1065 E. Hillsdale Blvd., Suite 215
> Foster City, CA 94404
> (650) 242-3500 Main
> www.truviso.com
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc
>

Hello Maciek,

okay, thanx for the clarifcation.
Here are the server side logs for the pgAdmin case:
2011-02-25 10:42:08 CET LOG:  duration: 98.226 ms  statement: execute t2
(1,7429);
2011-02-25 10:42:08 CET DETAIL:  prepare: prepare t2 (int4, int4) AS
          SELECT DISTINCT vec.*, s.statistic_difficulty as
examination_difficulty,
          s.statistic_discriminatorypower as
examination_discriminatorypower,
          vimc.mediacount,vis.difficulty, vis.discriminatorypower,
vis.statistic_counter, virc.reviewcount, u.user_surname
          FROM ims_vexaminationcontent vec
          LEFT OUTER JOIN ims_statistic s ON vec.item_id = s.object_id
AND s.examination_id = vec.examination_id
          LEFT OUTER JOIN ims_vitemmediacount vimc ON (vimc.item_id =
vec.item_id)
          LEFT OUTER JOIN ims_vitemstatistic vis ON (vis.item_id =
vec.item_id)
          INNER JOIN ims_user u on (author_id = u.user_id)
          LEFT OUTER JOIN ims_vitemreviewcount virc ON virc.item_id =
vec.item_id
          WHERE ((vec.examinationcontentversion_version=$1 AND
vec.examination_entityid=$2))
          ORDER BY vec.examinationcontentversion_sequenceno ASC NULLS LAST

Is there a chance to get the execution plan of the statement, when the
statement is executed through JDBC stack?

I have the same feeling about the edge case here, that is exactly why i
am writing to this list;-)
So still the question is how can i find out what is going on?

Yesterday i also looked at the debug level logs of the jdbc driver but i
found nothinng unusal.

Any more hints?

Thanx in advance
Lars

On 02/24/2011 07:38 PM, Maciek Sakrejda wrote:
> A named prepared statement (which you seem to be using through
> pgAdmin) is *not* the same thing as a PreparedStatement in JDBC. Most
> pertinently, JDBC is using an unnamed portal to execute the query,
> which delays planning until the parameters are provided. I don't think
> this ever happens with a named prepared statement (it would help if
> you provided server-side logs for the pgAdmin execution as well). The
> deferred planning behavior typically works to your advantage, but you
> may have run into some edge case here.
>
> Alternately, because the unnamed portal execution actually also does
> the planning, I presume it's counted in the time of the statement
> execution, whereas in the pgAdmin case, it looks like you're only
> timing the execute, which is going against an already-planned (at
> prepare time) query, so you may be comparing apples to oranges.
>
> ---
> Maciek Sakrejda | System Architect | Truviso
>
> 1065 E. Hillsdale Blvd., Suite 215
> Foster City, CA 94404
> (650) 242-3500 Main
> www.truviso.com
>

--
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Lars Feistner

Kompetenzzentrum für Prüfungen in der Medizin
Medizinische Fakultät Heidelberg,
Im Neuenheimer Feld 346, Raum 013
69120 Heidelberg

E-Mail: feistner@uni-heidelberg.de
Fon:   +49-6221-56-8269
Fax:   +49-6221-56-7175

WWW:   http://www.ims-m.de
        http://www.kompmed.de
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 On Fri, 25 Feb 2011 10:51:56 +0100, Lars Feistner wrote:
> Hello Maciek,
>
> okay, thanx for the clarifcation.
> Here are the server side logs for the pgAdmin case:
> 2011-02-25 10:42:08 CET LOG:  duration: 98.226 ms  statement: execute
> t2 (1,7429);
> 2011-02-25 10:42:08 CET DETAIL:  prepare: prepare t2 (int4, int4) AS
>          SELECT DISTINCT vec.*, s.statistic_difficulty as
> examination_difficulty,
>          s.statistic_discriminatorypower as
> examination_discriminatorypower,
>          vimc.mediacount,vis.difficulty, vis.discriminatorypower,
> vis.statistic_counter, virc.reviewcount, u.user_surname
>          FROM ims_vexaminationcontent vec
>          LEFT OUTER JOIN ims_statistic s ON vec.item_id = s.object_id
> AND s.examination_id = vec.examination_id
>          LEFT OUTER JOIN ims_vitemmediacount vimc ON (vimc.item_id =
> vec.item_id)
>          LEFT OUTER JOIN ims_vitemstatistic vis ON (vis.item_id =
> vec.item_id)
>          INNER JOIN ims_user u on (author_id = u.user_id)
>          LEFT OUTER JOIN ims_vitemreviewcount virc ON virc.item_id =
> vec.item_id
>          WHERE ((vec.examinationcontentversion_version=$1 AND
> vec.examination_entityid=$2))
>          ORDER BY vec.examinationcontentversion_sequenceno ASC NULLS
> LAST
>
> Is there a chance to get the execution plan of the statement, when
> the statement is executed through JDBC stack?
>
> I have the same feeling about the edge case here, that is exactly why
> i am writing to this list;-)
> So still the question is how can i find out what is going on?
>
> Yesterday i also looked at the debug level logs of the jdbc driver
> but i found nothinng unusal.
>
> Any more hints?
>
> Thanx in advance
> Lars
>
> On 02/24/2011 07:38 PM, Maciek Sakrejda wrote:
>> A named prepared statement (which you seem to be using through
>> pgAdmin) is *not* the same thing as a PreparedStatement in JDBC.
>> Most
>> pertinently, JDBC is using an unnamed portal to execute the query,
>> which delays planning until the parameters are provided. I don't
>> think
>> this ever happens with a named prepared statement (it would help if
>> you provided server-side logs for the pgAdmin execution as well).
>> The
>> deferred planning behavior typically works to your advantage, but
>> you
>> may have run into some edge case here.
>>
>> Alternately, because the unnamed portal execution actually also does
>> the planning, I presume it's counted in the time of the statement
>> execution, whereas in the pgAdmin case, it looks like you're only
>> timing the execute, which is going against an already-planned (at
>> prepare time) query, so you may be comparing apples to oranges.
>>
>> ---
>> Maciek Sakrejda | System Architect | Truviso
>>
>> 1065 E. Hillsdale Blvd., Suite 215
>> Foster City, CA 94404
>> (650) 242-3500 Main
>> www.truviso.com
>>
>
> --
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> Lars Feistner
>
> Kompetenzzentrum für Prüfungen in der Medizin
> Medizinische Fakultät Heidelberg,
> Im Neuenheimer Feld 346, Raum 013
> 69120 Heidelberg
>
> E-Mail: feistner@uni-heidelberg.de
> Fon:   +49-6221-56-8269
> Fax:   +49-6221-56-7175
>
> WWW:   http://www.ims-m.de
>        http://www.kompmed.de
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 At 90% it is backend problem, at this time I may only suggest you to
 try tunnelling (TUN/TAP or SSH) solutions over WAN or UMTS, which adds
 some nagle's algorithm (tcp_nodelay = false). JDBC driver design was
 much more better here.

 Regards,
 Radek.

Try an EXPLAIN ANALYZE, as Dave suggested. For JDBC, just do it for
the full statement. For the psql PREPARE / EXECUTE, you can only
explain analyze the execute, but that should tell us if the plans are
different.
---
Maciek Sakrejda | System Architect | Truviso

1065 E. Hillsdale Blvd., Suite 215
Foster City, CA 94404
(650) 242-3500 Main
www.truviso.com



On Fri, Feb 25, 2011 at 1:51 AM, Lars Feistner
<feistner@uni-heidelberg.de> wrote:
> Hello Maciek,
>
> okay, thanx for the clarifcation.
> Here are the server side logs for the pgAdmin case:
> 2011-02-25 10:42:08 CET LOG:  duration: 98.226 ms  statement: execute t2
> (1,7429);
> 2011-02-25 10:42:08 CET DETAIL:  prepare: prepare t2 (int4, int4) AS
>         SELECT DISTINCT vec.*, s.statistic_difficulty as
> examination_difficulty,
>         s.statistic_discriminatorypower as examination_discriminatorypower,
>         vimc.mediacount,vis.difficulty, vis.discriminatorypower,
> vis.statistic_counter, virc.reviewcount, u.user_surname
>         FROM ims_vexaminationcontent vec
>         LEFT OUTER JOIN ims_statistic s ON vec.item_id = s.object_id AND
> s.examination_id = vec.examination_id
>         LEFT OUTER JOIN ims_vitemmediacount vimc ON (vimc.item_id =
> vec.item_id)
>         LEFT OUTER JOIN ims_vitemstatistic vis ON (vis.item_id =
> vec.item_id)
>         INNER JOIN ims_user u on (author_id = u.user_id)
>         LEFT OUTER JOIN ims_vitemreviewcount virc ON virc.item_id =
> vec.item_id
>         WHERE ((vec.examinationcontentversion_version=$1 AND
> vec.examination_entityid=$2))
>         ORDER BY vec.examinationcontentversion_sequenceno ASC NULLS LAST
>
> Is there a chance to get the execution plan of the statement, when the
> statement is executed through JDBC stack?
>
> I have the same feeling about the edge case here, that is exactly why i am
> writing to this list;-)
> So still the question is how can i find out what is going on?
>
> Yesterday i also looked at the debug level logs of the jdbc driver but i
> found nothinng unusal.
>
> Any more hints?
>
> Thanx in advance
> Lars
>
> On 02/24/2011 07:38 PM, Maciek Sakrejda wrote:
>>
>> A named prepared statement (which you seem to be using through
>> pgAdmin) is *not* the same thing as a PreparedStatement in JDBC. Most
>> pertinently, JDBC is using an unnamed portal to execute the query,
>> which delays planning until the parameters are provided. I don't think
>> this ever happens with a named prepared statement (it would help if
>> you provided server-side logs for the pgAdmin execution as well). The
>> deferred planning behavior typically works to your advantage, but you
>> may have run into some edge case here.
>>
>> Alternately, because the unnamed portal execution actually also does
>> the planning, I presume it's counted in the time of the statement
>> execution, whereas in the pgAdmin case, it looks like you're only
>> timing the execute, which is going against an already-planned (at
>> prepare time) query, so you may be comparing apples to oranges.
>>
>> ---
>> Maciek Sakrejda | System Architect | Truviso
>>
>> 1065 E. Hillsdale Blvd., Suite 215
>> Foster City, CA 94404
>> (650) 242-3500 Main
>> www.truviso.com
>>
>
> --
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> Lars Feistner
>
> Kompetenzzentrum für Prüfungen in der Medizin
> Medizinische Fakultät Heidelberg,
> Im Neuenheimer Feld 346, Raum 013
> 69120 Heidelberg
>
> E-Mail: feistner@uni-heidelberg.de
> Fon:   +49-6221-56-8269
> Fax:   +49-6221-56-7175
>
> WWW:   http://www.ims-m.de
>       http://www.kompmed.de
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc
>