Thread: Extremely Low performance with ODBC
<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>
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 />
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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. +