Thread: Extremely Low performance with ODBC

Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
<div class="Section1"><p class="MsoNormal"><span lang="EN-US">Hi, I’m executing a query through psql ODBC which is
takingaround 2 minutes to complete. When I run it from PgAdmin it takes less than 3 seconds.</span><p
class="MsoNormal"><spanlang="EN-US">The query itself has :</span><p class="MsoNormal"><span lang="EN-US">. 15 inner
joins(from just around 10 different tables – the other inner joins are using different aliases for the same tables)
</span><pclass="MsoNormal"><span lang="EN-US">. Select statement returns 1 field.</span><p class="MsoNormal"><span
lang="EN-US">.the testing database is selecting only 1 record.</span><p class="MsoNormal"><span lang="EN-US"> </span><p
class="MsoNormal"><spanlang="EN-US">Taking a look at the explain analyze report, I see they are both quite the same and
testedthe ODBC driver through Visual Foxpro and Vb.NET as well, taking both around 2 minutes to finish.</span><p
class="MsoNormal"><spanlang="EN-US"> </span><p class="MsoNormal"><span lang="EN-US">Any idea ?</span><p
class="MsoNormal"><spanlang="EN-US"> </span><p class="MsoNormal"><span lang="EN-US">Thanks,</span><p
class="MsoNormal"><spanlang="EN-US"> </span><p class="MsoNormal"><span lang="EN-US">Sebastian</span></div> 

Re: Extremely Low performance with ODBC

From
Steve Crawford
Date:
Sebastian Rychter wrote: <blockquote cite="mid:004301c8bc39$c43aba40$4cb02ec0$@com.ar" type="cite"><style>
<!--/* Font Definitions */@font-face{font-family:"Cambria Math";panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face{font-family:Calibri;panose-1:2 15 5 2 2 2 4 3 2 4;}/* Style Definitions */p.MsoNormal, li.MsoNormal,
div.MsoNormal{margin:0cm;margin-bottom:.0001pt;font-size:11.0pt;font-family:"Calibri","sans-serif";}
a:link, span.MsoHyperlink{mso-style-priority:99;color:blue;text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed{mso-style-priority:99;color:purple;text-decoration:underline;}
span.EstiloCorreo17{mso-style-type:personal-compose;font-family:"Calibri","sans-serif";color:windowtext;}
.MsoChpDefault{mso-style-type:export-only;}
@page Section1{size:612.0pt 792.0pt;margin:70.85pt 3.0cm 70.85pt 3.0cm;}
div.Section1{page:Section1;}
--> </style><div class="Section1"><p class="MsoNormal"><span lang="EN-US">Hi, I’m executing a query through psql ODBC
whichis taking around 2 minutes to complete. When I run it from PgAdmin it takes less than 3 seconds.</span><p
class="MsoNormal"><spanlang="EN-US">The query itself has :</span><p class="MsoNormal"><span lang="EN-US">. 15 inner
joins(from just around 10 different tables – the other inner joins are using different aliases for the same tables)
</span><pclass="MsoNormal"><span lang="EN-US">. Select statement returns 1 field.</span><p class="MsoNormal"><span
lang="EN-US">.the testing database is selecting only 1 record.</span><p class="MsoNormal"><span lang="EN-US"> </span><p
class="MsoNormal"><spanlang="EN-US">Taking a look at the explain analyze report, I see they are both quite the same and
testedthe ODBC driver through Visual Foxpro and Vb.NET as well, taking both around 2 minutes to finish.</span><p
class="MsoNormal"><spanlang="EN-US"> </span><p class="MsoNormal"><span lang="EN-US">Any idea
?</span></div></blockquote>Don't know if this is your issue but we had a legacy VB/ODBC app that selected a handful (10
orfewer) records from a single table but for some reason behind the scenes we discovered that the app selected the
wholetable. As you might imagine, this caused very poor performance on large tables. EXPLAIN will not reveal this. You
mightwant to set the server to log all transactions and see what the app is really doing at the server level.<br /><br
/>Cheers,<br /> Steve<br /> 

Re: Extremely Low performance with ODBC

From
Craig Ringer
Date:
Sebastian Rychter wrote:
> Hi, I'm executing a query through psql ODBC which is taking around 2 minutes
> to complete. When I run it from PgAdmin it takes less than 3 seconds.
> 
> The query itself has :
> 
> . 15 inner joins (from just around 10 different tables - the other inner
> joins are using different aliases for the same tables) 
> 
> . Select statement returns 1 field.
> 
> . the testing database is selecting only 1 record.
> 
>  
> 
> Taking a look at the explain analyze report, I see they are both quite the
> same and tested the ODBC driver through Visual Foxpro and Vb.NET as well,
> taking both around 2 minutes to finish.

Are you using prepared statements (or might the driver be doing so for 
you) ?

A common question here arises from the query planner making different 
decisions for a query based on whether or not it can see the values of 
query parameters. Consider:

SELECT something FROM tablex WHERE somethingelse = ?

vs

SELECT something FROM tablex WHERE somethingelse = 4

My understanding is that if only (say) 0.1% of records have 
`somethingelse' = 4 and there's an index on `somethingelse' the planner 
will probably use the index for the second query. For the first query it 
won't know to use the index, especially if there are also values for 
`somethingelse' that occur a lot.

Try running your query in psql/pgadmin using PREPARE and EXECUTE and see 
if you get the same result.

--
Craig Ringer


Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Thu, May 22, 2008 at 11:29 AM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:
> Hi, I'm executing a query through psql ODBC which is taking around 2 minutes
> to complete. When I run it from PgAdmin it takes less than 3 seconds.
>
> Any idea ?

1) turn off all ODBC query logging from both the ODBC driver and the
ODBC administrator.  This feature is a performance killer.  Only use
this feature if you are trying to debug a problem.
2) Some client programs try to perform the joins on the client side
rather than the server side. I would check if the client is actually
passing the actual SQL statement back to the server. If it is trying
to perform the join on the client, it could be a big performance
killer.

-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
Thanks.. All logs are already off and I'm just sending one query directly
from the application (from Visual Foxpro using SQL Pass through and in
VB.net using ado.net). I've found that the "problem" is that I'm using
implicit joins, and when I change it to explicit Inner Joins the query only
takes 3 seconds (as with PgAdmin). I still can't understand if the problem
resides on the ODBC driver, the Query Planner or it's just a mix of both.

-----Mensaje original-----
De: Richard Broersma [mailto:richard.broersma@gmail.com] 
Enviado el: Viernes, 23 de Mayo de 2008 01:04 p.m.
Para: Sebastian Rychter
CC: pgsql-sql@postgresql.org
Asunto: Re: [SQL] Extremely Low performance with ODBC

On Thu, May 22, 2008 at 11:29 AM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:
> Hi, I'm executing a query through psql ODBC which is taking around 2
minutes
> to complete. When I run it from PgAdmin it takes less than 3 seconds.
>
> Any idea ?

1) turn off all ODBC query logging from both the ODBC driver and the
ODBC administrator.  This feature is a performance killer.  Only use
this feature if you are trying to debug a problem.
2) Some client programs try to perform the joins on the client side
rather than the server side. I would check if the client is actually
passing the actual SQL statement back to the server. If it is trying
to perform the join on the client, it could be a big performance
killer.

-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug

__________ NOD32 3124 (20080522) Information __________

This message was checked by NOD32 antivirus system.
http://www.eset.com




Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Fri, May 23, 2008 at 9:47 AM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:
> Thanks.. All logs are already off and I'm just sending one query directly
> from the application (from Visual Foxpro using SQL Pass through and in
> VB.net using ado.net). I've found that the "problem" is that I'm using
> implicit joins, and when I change it to explicit Inner Joins the query only
> takes 3 seconds (as with PgAdmin). I still can't understand if the problem
> resides on the ODBC driver, the Query Planner or it's just a mix of both.

The next step would be to turn on PostgreSQL's statement logging and
statement duration.  Issue the queries from VFP and then check what
statement that PG is actually getting.  If the statement that PG is
getting looks good, try executing that statement prefixed with explain
analyze from the psql command line to help identify where the
performance problem is.


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
Craig Ringer
Date:
Richard Broersma wrote:
> On Fri, May 23, 2008 at 9:47 AM, Sebastian Rychter
> <srychter@anvet.com.ar> wrote:
>> Thanks.. All logs are already off and I'm just sending one query directly
>> from the application (from Visual Foxpro using SQL Pass through and in
>> VB.net using ado.net). I've found that the "problem" is that I'm using
>> implicit joins, and when I change it to explicit Inner Joins the query only
>> takes 3 seconds (as with PgAdmin). I still can't understand if the problem
>> resides on the ODBC driver, the Query Planner or it's just a mix of both.
> 
> The next step would be to turn on PostgreSQL's statement logging and
> statement duration.  Issue the queries from VFP and then check what
> statement that PG is actually getting.  If the statement that PG is
> getting looks good, try executing that statement prefixed with explain
> analyze from the psql command line to help identify where the
> performance problem is.

You know what'd be incredibly handy for this sort of issue?

The ability to set an `always explain analyze' flag on a connection, 
preferably as a driver parameter (for ODBC/JDBC) or failing that as a 
per-connection variable like the ones to enable/disable seqscan, nested 
loop, etc.

That might really help with tracking down issues that appear to only 
happen with queries run by an app, or though a particular interface.

Can it be done? Or is the DB server not capable of generating explain 
output (say to a log) and also returning a resultset?

--
Craig Ringer



Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Fri, May 23, 2008 at 2:07 PM, Craig Ringer
<craig@postnewspapers.com.au> wrote:

> Can it be done? Or is the DB server not capable of generating explain output
> (say to a log) and also returning a resultset?

It can be done ~kind-of~.

To me EXPLAIN [ ANALYSE ] is similar to any other SELECT statement
query, with the exception that the data-set that it returns to the
client is an order list of execution steps.

So, if a client front-end were to pass an explain analyze query to the
server, the server would return the data-set for the execution plan.
The trick here is to find a way to get a client interface to prefix
its select statements with explain analyze.  And this, I don't thing
can be done.  That's why you have to manually view the server logs to
see what query are being passed so that identify the problem queries
your self.


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
Richard, 

Thanks for your response. I did that in the first place and found that both
explain reports where quite similar. I've got both reports: From pgadmin it
took 7288 ms, and from VFP took 6446 ms (of course, that's the time
calculated within the explain analyze, and not the real elapsed time).
That's why I assume the ODBC driver is taking its own time for parsing or
something like that- around 2 minutes actually :)
I already tried different syntax alternatives, removing and changing fields
from the Select statement, changing the order within the Where clause and
others just to find out the reason of this odd behavior.
I would change all the Inner joins to explicit ones, but in order to keep it
SQL ANSI compliant (and make it work with different RDMBS), we are not
allowed to use it that way. 

This is the whole query:
SELECT "Patient"."Patient_ID"
FROM "Patient","PatientFamily","PatientFamilyRole","Title","City" AS "PatientCity","City" AS "PatientAltCity","City" AS
"PatientEmployerCity","City"AS "PatientDoctorCity","Province" AS "PatientProvince","Province" AS
"PatientAltProvince","Province"AS "PatientEmployerProvince","Province" AS "PatientDoctorProvince","Country" AS
"PatientCountry","Country"AS "PatientAltCountry","Country" AS "PatientEmployerCountry","Country" AS
"PatientDoctorCountry"
 
WHERE "Patient"."Family_ID"="PatientFamily"."Family_ID" AND
"Patient"."FamilyRole_ID"="PatientFamilyRole"."FamilyRole_ID"AND"Patient"."Title_ID"="Title"."Title_ID"
AND"Patient"."City_ID"="PatientCity"."City_ID"AND"Patient"."Province_ID"="PatientProvince"."Province_ID" AND
"Patient"."Country_ID"="PatientCountry"."Country_ID"AND"Patient"."AltCity_ID"="PatientAltCity"."City_ID"
AND"Patient"."AltProvince_ID"="PatientAltProvince"."Province_ID"AND
"Patient"."AltCountry_ID"="PatientAltCountry"."Country_ID"AND
"Patient"."EmployerCity_ID"="PatientEmployerCity"."City_ID"AND
 
"Patient"."EmployerProvince_ID"="PatientEmployerProvince"."Province_ID"
AND"Patient"."EmployerCountry_ID"="PatientEmployerCountry"."Country_ID"
AND "Patient"."DoctorCity_ID"="PatientDoctorCity"."City_ID" AND
"Patient"."DoctorProvince_ID"="PatientDoctorProvince"."Province_ID"
AND"Patient"."DoctorCountry_ID"="PatientDoctorCountry"."Country_ID" AND
"Patient"."Patient_ID"=10450 
ORDER BY "Patient"."UDID" ASC

and the report when I ran it from VFP (through ODBC):
Sort  (cost=61.84..61.84 rows=1 width=23) (actual time=5.805..5.807 rows=1
loops=1) Sort Key: "Patient"."UDID" Sort Method:  quicksort  Memory: 17kB ->  Nested Loop  (cost=39.33..61.83 rows=1
width=23)(actual
 
time=4.738..5.771 rows=1 loops=1)       Join Filter: ("Patient"."FamilyRole_ID" =
"PatientFamilyRole"."FamilyRole_ID")       ->  Nested Loop  (cost=39.33..60.56 rows=1 width=27) (actual
time=4.679..5.705 rows=1 loops=1)             Join Filter: ("Patient"."Country_ID" =
"PatientCountry"."Country_ID")             ->  Nested Loop  (cost=39.33..59.51 rows=1 width=31) (actual
time=4.665..5.679 rows=1 loops=1)                   Join Filter: ("Patient"."AltCountry_ID" =
"PatientAltCountry"."Country_ID")                   ->  Nested Loop  (cost=39.33..58.47 rows=1 width=35)
(actual time=4.646..5.654 rows=1 loops=1)                         Join Filter: ("Patient"."EmployerCountry_ID" =
"PatientEmployerCountry"."Country_ID")                         ->  Nested Loop  (cost=39.33..57.42 rows=1
width=39) (actual time=4.628..5.629 rows=1 loops=1)                               Join Filter: ("Patient"."Title_ID" =
"Title"."Title_ID")                               ->  Nested Loop  (cost=39.33..56.20 rows=1
width=43) (actual time=4.597..5.572 rows=1 loops=1)                                     ->  Nested Loop
(cost=39.33..47.92
rows=1 width=47) (actual time=4.576..5.544 rows=1 loops=1)                                           Join Filter:
("Patient"."DoctorCountry_ID" = "PatientDoctorCountry"."Country_ID")                                           ->  Hash
Join
(cost=39.33..46.87 rows=1 width=51) (actual time=4.551..5.512 rows=1
loops=1)                                                 Hash Cond:
("PatientCity"."City_ID" = "Patient"."City_ID")                                                 ->  Seq Scan on "City"
"PatientCity"  (cost=0.00..6.57 rows=257 width=4) (actual time=0.020..0.505
rows=257 loops=1)                                                 ->  Hash
(cost=39.32..39.32 rows=1 width=55) (actual time=4.501..4.501 rows=1
loops=1)                                                       ->  Hash Join
(cost=31.77..39.32 rows=1 width=55) (actual time=3.528..4.492 rows=1
loops=1)                                                             Hash Cond:
("PatientAltCity"."City_ID" = "Patient"."AltCity_ID")                                                             ->
SeqScan
 
on "City" "PatientAltCity"  (cost=0.00..6.57 rows=257 width=4) (actual
time=0.005..0.486 rows=257 loops=1)                                                             ->  Hash
(cost=31.76..31.76 rows=1 width=59) (actual time=3.495..3.495 rows=1
loops=1)                                                                   ->  Hash
Join  (cost=24.22..31.76 rows=1 width=59) (actual time=2.515..3.486 rows=1
loops=1)
Hash Cond: ("PatientEmployerCity"."City_ID" = "Patient"."EmployerCity_ID")
                          ->
 
Seq Scan on "City" "PatientEmployerCity"  (cost=0.00..6.57 rows=257 width=4)
(actual time=0.004..0.486 rows=257 loops=1)                                                                         ->
Hash  (cost=24.20..24.20 rows=1 width=63) (actual time=2.483..2.483 rows=1
loops=1)
->  Hash Join  (cost=16.66..24.20 rows=1 width=63) (actual time=1.496..2.475
rows=1 loops=1)
Hash Cond: ("PatientDoctorCity"."City_ID" = "Patient"."DoctorCity_ID")
->  Seq Scan on "City" "PatientDoctorCity"  (cost=0.00..6.57 rows=257
width=4) (actual time=0.004..0.497 rows=257 loops=1)
->  Hash  (cost=16.65..16.65 rows=1 width=67) (actual time=1.464..1.464
rows=1 loops=1)
->  Hash Join  (cost=14.57..16.65 rows=1 width=67) (actual time=1.185..1.456
rows=1 loops=1)
Hash Cond: ("PatientProvince"."Province_ID" = "Patient"."Province_ID")
->  Seq Scan on "Province" "PatientProvince"  (cost=0.00..1.78 rows=78
width=4) (actual time=0.008..0.156 rows=78 loops=1)
->  Hash  (cost=14.55..14.55 rows=1 width=71) (actual time=1.131..1.131
rows=1 loops=1)
->  Hash Join  (cost=12.47..14.55 rows=1 width=71) (actual time=1.072..1.122
rows=1 loops=1)
Hash Cond: ("PatientAltProvince"."Province_ID" = "Patient"."AltProvince_ID")
->  Seq Scan on "Province" "PatientAltProvince"  (cost=0.00..1.78 rows=78
width=4) (actual time=0.005..0.149 rows=78 loops=1)
->  Hash  (cost=12.46..12.46 rows=1 width=75) (actual time=0.733..0.733
rows=1 loops=1)
->  Hash Join  (cost=10.38..12.46 rows=1 width=75) (actual time=0.675..0.725
rows=1 loops=1)
Hash Cond: ("PatientEmployerProvince"."Province_ID" =
"Patient"."EmployerProvince_ID")
->  Seq Scan on "Province" "PatientEmployerProvince"  (cost=0.00..1.78
rows=78 width=4) (actual time=0.005..0.147 rows=78 loops=1)
->  Hash  (cost=10.36..10.36 rows=1 width=79) (actual time=0.404..0.404
rows=1 loops=1)
->  Hash Join  (cost=8.28..10.36 rows=1 width=79) (actual time=0.345..0.396
rows=1 loops=1)
Hash Cond: ("PatientDoctorProvince"."Province_ID" =
"Patient"."DoctorProvince_ID")
->  Seq Scan on "Province" "PatientDoctorProvince"  (cost=0.00..1.78 rows=78
width=4) (actual time=0.005..0.150 rows=78 loops=1)
->  Hash  (cost=8.27..8.27 rows=1 width=83) (actual time=0.044..0.044 rows=1
loops=1)
->  Index Scan using "Patient_pkey" on "Patient"  (cost=0.00..8.27 rows=1
width=83) (actual time=0.028..0.032 rows=1 loops=1)
Index Cond: ("Patient_ID" = 10450)                                           ->  Seq Scan on "Country"
"PatientDoctorCountry"  (cost=0.00..1.02 rows=2 width=4) (actual
time=0.003..0.007 rows=2 loops=1)                                     ->  Index Scan using
"PatientFamily_pkey" on "PatientFamily"  (cost=0.00..8.27 rows=1 width=4)
(actual time=0.010..0.012 rows=1 loops=1)                                           Index Cond:
("PatientFamily"."Family_ID" = "Patient"."Family_ID")                               ->  Seq Scan on "Title"
(cost=0.00..1.10
rows=10 width=4) (actual time=0.004..0.023 rows=10 loops=1)                         ->  Seq Scan on "Country"
"PatientEmployerCountry"
(cost=0.00..1.02 rows=2 width=4) (actual time=0.003..0.007 rows=2 loops=1)                   ->  Seq Scan on "Country"
"PatientAltCountry"
(cost=0.00..1.02 rows=2 width=4) (actual time=0.003..0.006 rows=2 loops=1)             ->  Seq Scan on "Country"
"PatientCountry" (cost=0.00..1.02
 
rows=2 width=4) (actual time=0.003..0.006 rows=2 loops=1)       ->  Seq Scan on "PatientFamilyRole"  (cost=0.00..1.12
rows=12
width=4) (actual time=0.004..0.026 rows=12 loops=1)
Total runtime: 6.446 ms

-----Mensaje original-----
De: pgsql-sql-owner@postgresql.org [mailto:pgsql-sql-owner@postgresql.org]
En nombre de Richard Broersma
Enviado el: Viernes, 23 de Mayo de 2008 05:26 p.m.
Para: Sebastian Rychter
CC: pgsql-sql@postgresql.org
Asunto: Re: [SQL] Extremely Low performance with ODBC

On Fri, May 23, 2008 at 9:47 AM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:
> Thanks.. All logs are already off and I'm just sending one query directly
> from the application (from Visual Foxpro using SQL Pass through and in
> VB.net using ado.net). I've found that the "problem" is that I'm using
> implicit joins, and when I change it to explicit Inner Joins the query
only
> takes 3 seconds (as with PgAdmin). I still can't understand if the problem
> resides on the ODBC driver, the Query Planner or it's just a mix of both.

The next step would be to turn on PostgreSQL's statement logging and
statement duration.  Issue the queries from VFP and then check what
statement that PG is actually getting.  If the statement that PG is
getting looks good, try executing that statement prefixed with explain
analyze from the psql command line to help identify where the
performance problem is.


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug

-- 
Sent via pgsql-sql mailing list (pgsql-sql@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-sql

__________ NOD32 3127 (20080523) Information __________

This message was checked by NOD32 antivirus system.
http://www.eset.com




Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Fri, May 23, 2008 at 2:45 PM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:

> Thanks for your response. I did that in the first place and found that both
> explain reports where quite similar. I've got both reports: From pgadmin it
> took 7288 ms, and from VFP took 6446 ms (of course, that's the time
> calculated within the explain analyze, and not the real elapsed time).

actually it looks like 7.288ms and 6.446ms. ;)

> That's why I assume the ODBC driver is taking its own time for parsing or
> something like that- around 2 minutes actually :)

Checking the Postgresql logs would be really helpful here.

1) note the time that you issue the query from your client FE.
2) note the time in the pg server logs that the server gets the passed
query string.
2b) check for any disparity between 1) and 2).
3) check that the query is exactly the same as you've hand coded in pg-admin
4) also check the query duration when issued by ODBC in the postgresql
log to see if it is really taking 2 minutes.

It would be nice to see the snippet of the PG log showing this ODBC
query with associate duration times.

-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
Richard, 

I'm not sure if this is the kind of log that you meant, but the one in
pg_log goes like this (the first query corresponding to the ODBC execution
(112157 ms), the second one is from pgAdmin (250 ms). I also logged for the
ODBC driver but didn't find any differences between the steps followed in
both cases.

2008-05-27 02:55:10 GMT LOG:  duration: 112157.000 ms  statement: SELECT
"Patient"."Patient_ID"FROM "Patient",    "PatientFamily",    "PatientFamilyRole",    "Title",    "City" PatientCity,
"City"PatientAltCity,    "City" PatientEmployerCity,    "City" PatientDoctorCity,    "Province" PatientProvince,
"Province"PatientAltProvince,    "Province" PatientEmployerProvince,    "Province" PatientDoctorProvince,    "Country"
PatientCountry,   "Country" PatientAltCountry,    "Country" PatientEmployerCountry,    "Country"
PatientDoctorCountryWHERE"Patient"."Family_ID"="PatientFamily"."Family_ID" AND 
 
"Patient"."FamilyRole_ID"="PatientFamilyRole"."FamilyRole_ID" AND    "Patient"."Title_ID"="Title"."Title_ID" AND
"Patient"."City_ID"=PatientCity."City_ID"AND    "Patient"."Province_ID"=PatientProvince."Province_ID" AND
"Patient"."Country_ID"=PatientCountry."Country_ID"AND    "Patient"."AltCity_ID"=PatientAltCity."City_ID" AND
"Patient"."AltProvince_ID"=PatientAltProvince."Province_ID"
AND      "Patient"."AltCountry_ID"=PatientAltCountry."Country_ID" AND
"Patient"."EmployerCity_ID"=PatientEmployerCity."City_ID"AND
 
"Patient"."EmployerProvince_ID"=PatientEmployerProvince."Province_ID" AND
"Patient"."EmployerCountry_ID"=PatientEmployerCountry."Country_ID" AND
"Patient"."DoctorCity_ID"=PatientDoctorCity."City_ID"AND 
 
"Patient"."DoctorProvince_ID"=PatientDoctorProvince."Province_ID" AND
"Patient"."DoctorCountry_ID"=PatientDoctorCountry."Country_ID"
AND       "Patient"."Patient_ID"=10450
2008-05-27 03:00:07 GMT LOG:  loaded library
"$libdir/plugins/plugin_debugger.dll"
2008-05-27 03:00:08 GMT LOG:  duration: 108.999 ms  statement: set
client_encoding to 'UNICODE'
2008-05-27 03:00:11 GMT LOG:  loaded library
"$libdir/plugins/plugin_debugger.dll"
2008-05-27 03:00:12 GMT LOG:  loaded library
"$libdir/plugins/plugin_debugger.dll"
2008-05-27 03:00:14 GMT ERROR:  unterminated quoted string at or near "' "
at character 554
2008-05-27 03:00:14 GMT STATEMENT:  select n.nspname, c.relname, a.attname,
a.atttypid, t.typname, a.attnum, a.attlen, a.atttypmod, a.attnotnull,
c.relhasrules, c.relkind, c.oid, d.adsrc from (((pg_catalog.pg_class c inner
join pg_catalog.pg_namespace n on n.oid = c.relnamespace and c.oid =
3368883) inner join pg_catalog.pg_attribute a on (not a.attisdropped) and
a.attnum > 0 and a.attrelid = c.oid) inner join pg_catalog.pg_type t on
t.oid = a.atttypid) left outer join pg_attrdef d on a.atthasdef and
d.adrelid = a.attrelid and d.adnum = a.attnum order by n.nspname, c.relname,
attnum' 
2008-05-27 03:07:29 GMT LOG:  duration: 250.000 ms  statement: SELECT
"Patient"."Patient_ID"    FROM "Patient",        "PatientFamily",        "PatientFamilyRole",        "Title",
"City"PatientCity,        "City" PatientAltCity,        "City" PatientEmployerCity,        "City" PatientDoctorCity,
   "Province" PatientProvince,        "Province" PatientAltProvince,        "Province" PatientEmployerProvince,
"Province"PatientDoctorProvince,        "Country" PatientCountry,        "Country" PatientAltCountry,        "Country"
PatientEmployerCountry,       "Country" PatientDoctorCountry    WHERE "Patient"."Family_ID"="PatientFamily"."Family_ID"
AND
 
"Patient"."FamilyRole_ID"="PatientFamilyRole"."FamilyRole_ID" AND        "Patient"."Title_ID"="Title"."Title_ID" AND
   "Patient"."City_ID"=PatientCity."City_ID" AND
 
"Patient"."Province_ID"=PatientProvince."Province_ID" AND         "Patient"."Country_ID"=PatientCountry."Country_ID"
AND        "Patient"."AltCity_ID"=PatientAltCity."City_ID" AND
"Patient"."AltProvince_ID"=PatientAltProvince."Province_ID" AND
"Patient"."AltCountry_ID"=PatientAltCountry."Country_ID" AND 
"Patient"."EmployerCity_ID"=PatientEmployerCity."City_ID" AND
"Patient"."EmployerProvince_ID"=PatientEmployerProvince."Province_ID" AND
"Patient"."EmployerCountry_ID"=PatientEmployerCountry."Country_ID" AND
"Patient"."DoctorCity_ID"=PatientDoctorCity."City_ID"
AND 
"Patient"."DoctorProvince_ID"=PatientDoctorProvince."Province_ID" AND
"Patient"."DoctorCountry_ID"=PatientDoctorCountry."Country_ID" AND           "Patient"."Patient_ID"=10450    

-----Mensaje original-----
De: Richard Broersma [mailto:richard.broersma@gmail.com] 
Enviado el: Viernes, 23 de Mayo de 2008 07:00 p.m.
Para: Sebastian Rychter
CC: pgsql-sql@postgresql.org
Asunto: Re: [SQL] Extremely Low performance with ODBC

On Fri, May 23, 2008 at 2:45 PM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:

> Thanks for your response. I did that in the first place and found that
both
> explain reports where quite similar. I've got both reports: From pgadmin
it
> took 7288 ms, and from VFP took 6446 ms (of course, that's the time
> calculated within the explain analyze, and not the real elapsed time).

actually it looks like 7.288ms and 6.446ms. ;)

> That's why I assume the ODBC driver is taking its own time for parsing or
> something like that- around 2 minutes actually :)

Checking the Postgresql logs would be really helpful here.

1) note the time that you issue the query from your client FE.
2) note the time in the pg server logs that the server gets the passed
query string.
2b) check for any disparity between 1) and 2).
3) check that the query is exactly the same as you've hand coded in pg-admin
4) also check the query duration when issued by ODBC in the postgresql
log to see if it is really taking 2 minutes.

It would be nice to see the snippet of the PG log showing this ODBC
query with associate duration times.

-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug

__________ NOD32 3127 (20080523) Information __________

This message was checked by NOD32 antivirus system.
http://www.eset.com




Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Mon, May 26, 2008 at 8:26 PM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:

> 2008-05-27 02:55:10 GMT LOG:  duration: 112157.000 ms  statement: SELECT
> 2008-05-27 03:07:29 GMT LOG:  duration: 250.000 ms  statement: SELECT

Wow, that is a big difference.  I reformated your querys and diff'ed
them.  You are correct, they are exactly the same query.  My only
other guess would be that the first time you execute this query using
ODBC, you need to get a fresh read from disk.  However, once this
dataset is cached in memory it returns much faster when you requery it
using PGAdmin.  If you run the same query twice conseqitively in ODBC,
does the second query perform much better or do both querys perform
badly?

If they both odbc queries perform badly, the last thing that I would
try would be to capture the results of :

EXPLAIN ANALYZE SELECT ...(your query), from both ODBC, and PGADMIN.
If we compare them It should at least tell us what the server is doing
differently that is causing the query mis-behavior.


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
I already tried executing them in different order, but that only affects in
just a few milliseconds (the one with explicit joins remains much faster).
The bad news is that I already compared both Explain Analyze results (from
pgAdmin and ODBC) and they follow the same steps. I also tried comparing the
Explain Analyze between the Explicit Join and the Implicit Join, and though
they are different, the Total time is almost the same.

I'll keep on looking for any other differences on different logs.. I think I
already searched all the Postgresql forums I know and no one ever reported
something like that before.

Thanks once again,

Sebastian

-----Mensaje original-----
De: Richard Broersma [mailto:richard.broersma@gmail.com] 
Enviado el: Martes, 27 de Mayo de 2008 01:14 a.m.
Para: Sebastian Rychter
CC: pgsql-sql@postgresql.org
Asunto: Re: [SQL] Extremely Low performance with ODBC

On Mon, May 26, 2008 at 8:26 PM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:

> 2008-05-27 02:55:10 GMT LOG:  duration: 112157.000 ms  statement: SELECT
> 2008-05-27 03:07:29 GMT LOG:  duration: 250.000 ms  statement: SELECT

Wow, that is a big difference.  I reformated your querys and diff'ed
them.  You are correct, they are exactly the same query.  My only
other guess would be that the first time you execute this query using
ODBC, you need to get a fresh read from disk.  However, once this
dataset is cached in memory it returns much faster when you requery it
using PGAdmin.  If you run the same query twice conseqitively in ODBC,
does the second query perform much better or do both querys perform
badly?

If they both odbc queries perform badly, the last thing that I would
try would be to capture the results of :

EXPLAIN ANALYZE SELECT ...(your query), from both ODBC, and PGADMIN.
If we compare them It should at least tell us what the server is doing
differently that is causing the query mis-behavior.


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug

__________ NOD32 3133 (20080526) Information __________

This message was checked by NOD32 antivirus system.
http://www.eset.com




Re: Extremely Low performance with ODBC

From
"Richard Broersma"
Date:
On Mon, May 26, 2008 at 9:34 PM, Sebastian Rychter
<srychter@anvet.com.ar> wrote:

> I'll keep on looking for any other differences on different logs.. I think I
> already searched all the Postgresql forums I know and no one ever reported
> something like that before.

There is one other thing that you should also do.  The pgSQL mailing
list really isn't the most applicable mailing list for ODBC or
PERFORMANCE problems with postgresql.

Here is what you should do:

send an email to both the pgODBC and pgPerformance mailing lists that
contain the following:

a brief recap of the problem you are having and,

the log snippet for each query( one from ODBC and one from PGadmin )
(I would attach these as a txt file)

the EXPLAIN ANALYZE of your query ( on run from the ODBC client and on
from PGadmin) (I would attach these as a txt file)


-- 
Regards,
Richard Broersma Jr.

Visit the Los Angles PostgreSQL Users Group (LAPUG)
http://pugs.postgresql.org/lapug


Re: Extremely Low performance with ODBC

From
Steve Midgley
Date:
At 09:20 PM 5/27/2008, pgsql-sql-owner@postgresql.org wrote:
>Date: Tue, 27 May 2008 09:29:56 -0700
>From: "Richard Broersma" <richard.broersma@gmail.com>
>To: "Sebastian Rychter" <srychter@anvet.com.ar>
>Cc: pgsql-sql@postgresql.org
>Subject: Re: Extremely Low performance with ODBC
>Message-ID: 
><396486430805270929y6bc3cfcidba5a38592e433e9@mail.gmail.com>
>
>On Mon, May 26, 2008 at 9:34 PM, Sebastian Rychter
><srychter@anvet.com.ar> wrote:
>
> > I'll keep on looking for any other differences on different logs.. 
> I think I
> > already searched all the Postgresql forums I know and no one ever 
> reported
> > something like that before.

I've been following this discussion with interest - years ago I was 
responsible for a high performance web system that used ODBC in the 
data layer (not quite an oxymoron there). But I haven't touched ODBC 
since 2001! (Be warned)..

With performance times that slow it seems like there are a couple of 
possibilities that I can think of. To narrow down the choices:

How many rows does your query return? If it's returning a lot try 
running the exact same query but with a "limit 10" on the end - does 
that take just as long to run or does it come back quickly?

Here are some other ideas:

1) The Pg ODBC driver is broken and is looping internally in some wrong 
way, when constructing your result set. This seems a little unlikely 
but totally possible. The groups that Richard recommends can probably 
help on this end.

2) Your ODBC DSN is misconfigured. This seems more likely to me. You 
may already be an expert with ODBC and have it correctly configured, in 
which disregard this. But the Pg ODBC interface has a lot of unique 
options and any one or combination could be spiking your results speed. 


Have you played with the various config options in the advanced window 
of "odbcad32.exe" when creating a data source with a Pg ODBC driver?

For example, try toggling "Keyset query optimization" or "Use 
Declare/Fetch" - Also, does the "cache size" setting impact your query 
speed at all? There are a number of checkboxes here that seem like they 
might affect your situation. Be sure all the logging is turned off when 
testing performance.

Also, "updatable cursors" is turned on by default (on my copy of Pg 
ODBC) - that seems "wrong" and you might try your search with it turned 
off. Also "server side prepare" is turned off on my copy, and this also 
seems wrong - any diff with it turned on?

Another idea: when you run the query and it takes a long time, is the 
CPU spiked on your client machine or on the SQL Server or neither (if 
they're on the same machine, look in Task Manager to see which process 
is eating CPU). If it's not spiked anywhere, then it's possible that 
your problem is with a network socket timeout or something similar. 
Maybe use wire shark or something to watch your network traffic to dig 
deeper if this seems possible.

Others may have a more clear idea as to what these various ODBC options 
are for, but in my distant memories, fiddling with ODBC settings when 
doing performance tuning can make a big, big difference in how an 
application performs.

My whole goal in this regard was to find the settings in ODBC that 
caused ODBC to do as absolutely little as possible. Just receive raw 
sql, pipe it to my server and hand it back to me in a memory data 
structure. All the data structure parsing was done by my middleware 
connection wrapper to ODBC and none was done by ODBC itself. Once I got 
to that point, I was able to get some decent performance out of ODBC.

I hope some of these ideas helps! Feel free to write back on or off 
list.

Sincerely,

Steve



Re: Extremely Low performance with ODBC

From
Steve Midgley
Date:
At 09:20 PM 5/27/2008, pgsql-sql-owner@postgresql.org wrote:
>Date: Tue, 27 May 2008 09:29:56 -0700
>From: "Richard Broersma" <richard.broersma@gmail.com>
>To: "Sebastian Rychter" <srychter@anvet.com.ar>
>Cc: pgsql-sql@postgresql.org
>Subject: Re: Extremely Low performance with ODBC
>Message-ID: 
><396486430805270929y6bc3cfcidba5a38592e433e9@mail.gmail.com>
>
>On Mon, May 26, 2008 at 9:34 PM, Sebastian Rychter
><srychter@anvet.com.ar> wrote:
>
> > I'll keep on looking for any other differences on different logs.. 
> I think I
> > already searched all the Postgresql forums I know and no one ever 
> reported
> > something like that before.

Apologies for the double post on this - I wonder also if you have tried 
alternative Pg ODBC drivers? I found this one while googling around:

http://uda.openlinksw.com/odbc/st/odbc-progress-st/

But I'd guess there are other alternatives. Also, you might check out 
their ADO driver and see if it gives you the same problems..

Just some more grist for the solution mill, hopefully!

Steve



Re: Extremely Low performance with ODBC

From
"Sebastian Rychter"
Date:
Thanks. Hiroshi sent me a possible solution (which might be useful for
others going through similar situations), which is to toggle off the
"Disable Genetic Optimizer" from the ODBC driver configuration.

-----Mensaje original-----
De: pgsql-sql-owner@postgresql.org [mailto:pgsql-sql-owner@postgresql.org]
En nombre de Steve Midgley
Enviado el: Miércoles, 28 de Mayo de 2008 03:29 a.m.
Para: pgsql-sql-owner@postgresql.org; pgsql-sql@postgresql.org
CC: srychter@anvet.com.ar
Asunto: Re: [SQL] Extremely Low performance with ODBC

At 09:20 PM 5/27/2008, pgsql-sql-owner@postgresql.org wrote:
>Date: Tue, 27 May 2008 09:29:56 -0700
>From: "Richard Broersma" <richard.broersma@gmail.com>
>To: "Sebastian Rychter" <srychter@anvet.com.ar>
>Cc: pgsql-sql@postgresql.org
>Subject: Re: Extremely Low performance with ODBC
>Message-ID:
><396486430805270929y6bc3cfcidba5a38592e433e9@mail.gmail.com>
>
>On Mon, May 26, 2008 at 9:34 PM, Sebastian Rychter
><srychter@anvet.com.ar> wrote:
>
> > I'll keep on looking for any other differences on different logs..
> I think I
> > already searched all the Postgresql forums I know and no one ever
> reported
> > something like that before.

Apologies for the double post on this - I wonder also if you have tried
alternative Pg ODBC drivers? I found this one while googling around:

http://uda.openlinksw.com/odbc/st/odbc-progress-st/

But I'd guess there are other alternatives. Also, you might check out
their ADO driver and see if it gives you the same problems..

Just some more grist for the solution mill, hopefully!

Steve


--
Sent via pgsql-sql mailing list (pgsql-sql@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-sql

__________ NOD32 3137 (20080527) Information __________

This message was checked by NOD32 antivirus system.
http://www.eset.com




Re: Extremely Low performance with ODBC

From
Bruce Momjian
Date:
Sebastian Rychter wrote:
> Thanks. Hiroshi sent me a possible solution (which might be useful for
> others going through similar situations), which is to toggle off the
> "Disable Genetic Optimizer" from the ODBC driver configuration.

Uh, why is ODBC modifyingin the 'geqo' variable?

--  Bruce Momjian  <bruce@momjian.us>        http://momjian.us EnterpriseDB
http://enterprisedb.com
 + If your life is a hard drive, Christ can be your backup. +