Thread: Access 2003 reports queries taking very long
Hello,
I posted previously about a SELECT * query taking very long from an old IIS server with ODBC connector. Our developer fixed that, but he is away again.
Another performance issue I see in pgBadger is some queries from reports that are run on a Windows XP box in Access 2003 using ODBC. I assumed before that the query was just harsh, but when I run it myself, it takes 60ms. However whenever Access runs it (same time each day) it takes up to 18 seconds. All other queries take a maximum of 0.2seconds and we have over 200,000 queries a day now.
Any ideas on why the big discrepancy below? This time I should be able to get access to Access (sorry) on that report box, and we may even be able to point it to a development copy of the db and run it at will to troubleshoot. Below is the log from postgres and a manual explain.
I only changed "ourcompany" and "ourtable" below.
Thanks!
Andrew
ourcompany=# EXPLAIN ANALYZE SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable";
QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Seq Scan on ourtable (cost=0.00..5927.83 rows=88983 width=92) (actual time=0.013..56.392 rows=89196 loops=1)
Total runtime: 60.659 ms
(2 rows)
ourcompany=#
2014-02-12 09:11:41 EST [18238]: [1-1] user=[unknown],db=[unknown] LOG: connection received: host=::1 port=36670
2014-02-12 09:11:41 EST [18238]: [2-1] user=ourcompany,db=ourcompany LOG: connection authorized: user=ourcompany database=ourcompany
2014-02-12 09:11:41 EST [18238]: [3-1] user=ourcompany,db=ourcompany LOG: duration: 0.777 ms statement: select oid, typbasetype from pg_type where typname = 'lo'
2014-02-12 09:11:41 EST [18238]: [3-1] user=ourcompany,db=ourcompany LOG: duration: 0.777 ms statement: select oid, typbasetype from pg_type where typname = 'lo'
2014-02-12 09:11:41 EST [18238]: [4-1] user=ourcompany,db=ourcompany LOG: duration: 0.324 ms statement: set client_encoding to 'WIN1252'
2014-02-12 09:11:41 EST [18238]: [5-1] user=ourcompany,db=ourcompany ERROR: relation "msysconf" does not exist at character 28
2014-02-12 09:11:41 EST [18238]: [6-1] user=ourcompany,db=ourcompany STATEMENT: SELECT Config, nValue FROM MSysConf
2014-02-12 09:11:55 EST [18238]: [7-1] user=ourcompany,db=ourcompany LOG: duration: 14405.822 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:12:04 EST [18238]: [8-1] user=ourcompany,db=ourcompany LOG: duration: 6580.752 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:12:30 EST [18238]: [9-1] user=ourcompany,db=ourcompany LOG: duration: 18914.892 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:12:38 EST [18238]: [10-1] user=ourcompany,db=ourcompany LOG: duration: 6085.592 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:12:56 EST [18238]: [11-1] user=ourcompany,db=ourcompany LOG: duration: 12371.690 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:13:05 EST [18238]: [12-1] user=ourcompany,db=ourcompany LOG: duration: 6866.890 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:13:27 EST [18238]: [13-1] user=ourcompany,db=ourcompany LOG: duration: 17931.457 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:13:36 EST [18238]: [14-1] user=ourcompany,db=ourcompany LOG: duration: 7144.584 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:13:51 EST [18238]: [15-1] user=ourcompany,db=ourcompany LOG: duration: 12159.084 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:14:00 EST [18238]: [16-1] user=ourcompany,db=ourcompany LOG: duration: 6231.878 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:14:22 EST [18238]: [17-1] user=ourcompany,db=ourcompany LOG: duration: 18596.817 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
2014-02-12 09:14:31 EST [18238]: [18-1] user=ourcompany,db=ourcompany LOG: duration: 6960.412 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
2014-02-12 09:14:35 EST [18238]: [19-1] user=ourcompany,db=ourcompany LOG: disconnection: session time: 0:02:54.276 user=ourcompany database=ourcompany host=::1 port=36670
On Wed, Feb 12, 2014 at 3:53 PM, Andrew Puschak <apuschak@gmail.com> wrote: > 2014-02-12 09:14:00 EST [18238]: [16-1] user=ourcompany,db=ourcompany LOG: duration: 6231.878 ms statement: SELECT "savedt","clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable" > 2014-02-12 09:14:22 EST [18238]: [17-1] user=ourcompany,db=ourcompany LOG: duration: 18596.817 ms statement: SELECT "savedt","jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable" The only difference I see is in the number of columns, but it is quite strange that having the two queries ran at such a small time the data is not cached. Is there anything that happened on the cluster (even outside outable) in the meantime? Luca
On Sat, Feb 15, 2014 at 5:43 AM, Luca Ferrari <fluca1978@infinito.it> wrote:
On Wed, Feb 12, 2014 at 3:53 PM, Andrew Puschak <apuschak@gmail.com> wrote:The only difference I see is in the number of columns, but it is quite
> 2014-02-12 09:14:00 EST [18238]: [16-1] user=ourcompany,db=ourcompany LOG: duration: 6231.878 ms statement: SELECT "savedt" ,"clid_name" ,"hrs" ,"purpose" ,"howlong" FROM "public"."ourtable"
> 2014-02-12 09:14:22 EST [18238]: [17-1] user=ourcompany,db=ourcompany LOG: duration: 18596.817 ms statement: SELECT "savedt" ,"jobid" ,"emid" ,"clid_name" ,"hrs" ,"jname" ,"lname" ,"purpose" ,"howlong" ,"clid" ,"w_min" ,"m1" FROM "public"."ourtable"
strange that having the two queries ran at such a small time the data
is not cached. Is there anything that happened on the cluster (even
outside outable) in the meantime?
Luca
Hi Luca,
Thank you for your reply. I'm not sure what you mean by anything else happening? We have a lot of queries throughout the day, however there's nothing abnormal when these long queries occur in the postgres log. The postgres log is logging every query for pgBadger so it should show if there's something else going on at that time I think. The only difference seems to be that they come from Access through the ODBC connector. We are only using one database in the cluster and everything is relatively simple, although high volume.
Andrew
On Mon, Feb 17, 2014 at 3:36 PM, Andrew Puschak <apuschak@gmail.com> wrote: > > The only difference > seems to be that they come from Access through the ODBC connector. We are > only using one database in the cluster and everything is relatively simple, > although high volume. This would lead to a problem in the ODBC connector, even if I don't understand what would make a single statement to become so slow. Any chance you can run the same statement thru an ODBC connecter via a test program? Luca
Hi Luca,
I'm going to restore a backup dump to a dev server and have the owner connect to it. We should be able to troubleshoot the connection and recreate the problem. I'll let you know what we find out.
Andrew
On Tue, Feb 18, 2014 at 6:42 AM, Luca Ferrari <fluca1978@infinito.it> wrote:
On Mon, Feb 17, 2014 at 3:36 PM, Andrew Puschak <apuschak@gmail.com> wrote:This would lead to a problem in the ODBC connector, even if I don't
>
> The only difference
> seems to be that they come from Access through the ODBC connector. We are
> only using one database in the cluster and everything is relatively simple,
> although high volume.
understand what would make a single statement to become so slow. Any
chance you can run the same statement thru an ODBC connecter via a
test program?
Luca
Andrew Puschak
(267) 614 - 2373
apuschak@gmail.com
http://andrewpuschak.com