Slow Access Query cured by the Profiler...

I am using ReStore with a 109 MB Access database.  ReStore uses an ODBC
DBConnection under the hood.  I am trying to optimize a reporting task.  It
involves retrieving some composite objects from the database and combining
them (one could think of it like summing).  When I use my existing ReStore
code there are periods of time where things seem to come to a standstill
during processing, taking much longer than I would expect.  When I tried to
use Ian's wonderful profiler to study the problem I found that it cured it.
I guess Heisenberg has reared his head here. ;)  I turned on SQL logging in
ReStore (which also turns off the use of parameterized statements).  I can
see that the slow down was occurring on some select statements.  I grabbed
one of the statements and found that it could take ~8 seconds to complete
the first time I ran it after my reporting.  If I ran the statement again it
was very fast, 33 ms.  If I reconnected to the database I could run the
query in 373 ms the first time and then 33 ms thereafter.

What puzzles me a bit is why the Profiler seems to cure the problem.  I will
be investigating this further, but I was just wondering if this issue was
familiar to any one else?  I even tried forcing a GC via
MemoryManager current collectGarbage; administerLastRites.
but that did not produce any improvement.

Chris

Chris,

> I am using ReStore with a 109 MB Access database.  ReStore uses an ODBC
> DBConnection under the hood.  I am trying to optimize a reporting task.  It
> involves retrieving some composite objects from the database and combining
> them (one could think of it like summing).  When I use my existing ReStore
> code there are periods of time where things seem to come to a standstill
> during processing, taking much longer than I would expect.  When I tried to
> use Ian's wonderful profiler to study the problem I found that it cured it.

Other than my lead theory, which is that Ian's code is so good that some
of the quality rubbed off on the other subsystems<g>, I suspect that the
GUI thread might be getting blocked to your cost.  Have you tried
evaluating the SQL statements on a background thread?  Doing so might
give the same improvement.

It's been a long time in computer years, but I once relied heavily on
COM/DCOM, and at one point had some problems with systems "stalling".
IIRC, Blair both had me change some things and made some changes to
Dolphin as a result.


> I guess Heisenberg has reared his head here. ;)  I turned on SQL logging in
> ReStore (which also turns off the use of parameterized statements).  I can
> see that the slow down was occurring on some select statements.  I grabbed
> one of the statements and found that it could take ~8 seconds to complete
> the first time I ran it after my reporting.  If I ran the statement again it
> was very fast, 33 ms.  If I reconnected to the database I could run the
> query in 373 ms the first time and then 33 ms thereafter.

Some of that could be the COM objects that are loaded.  The 8 second hit
  has me suspecting network activity, but that seems unlikely given
Access as the DBMS.  You also made reference to prepared statements,
which could explain the boost.



> I even tried forcing a GC via
> MemoryManager current collectGarbage; administerLastRites.
> but that did not produce any improvement.

In my experience, that would matter only if you get into problems with
not enough cursors, etc.  I know the high water mark is supposed to
prevent such problems, but I found otherwise, even on win2k.

Have a good one,

Bill

--
Wilhelm K. Schwab, Ph.D.
[hidden email]

Chris,

> When I use my
> existing ReStore code there are periods of time where things seem to come
> to a standstill during processing, taking much longer than I would
> expect.  When I tried to use Ian's wonderful profiler to study the
> problem I found that it cured it.

Interesting effect.  I know that one is supposed to use a profiler to cure
performance problems, but it's not usually /that/ easy...


> What puzzles me a bit is why the Profiler seems to cure the problem.  I
> will be investigating this further, but I was just wondering if this
> issue was familiar to any one else?

At the risk of sending you on a complete wild-goose chase, this reminds me (a
bit) of a problem that Bill Dargel found, and which is described here:

    http://groups.google.co.uk/groups?threadm=3E77BC24.5DF982EC%40shoshana.com


At least, Ian's profiler doesn't do very much (that's relevant), it just sets a
timer and wakes up from time to time (see
Profiler>>sampleProcess:forSet:elapsedTime:ignoring:).  Which reminds me of the
way that a similar demon Process in my image prevented me from seeing the
problem that Bill reported.

All this is on the assumption that Access always finishes its work in a few
milliseconds, and the delay is cause by Dolphin not realising that it's
finished and waking up -- which may be completely false.  What happens to the
CPU load during those 8-second delays ?  Also, if you run the reporting in one
image, and then execute the test SQL in another image, does that eliminate the
8 second delay ?

    -- chris

"Christopher J. Demers" <[hidden email]> wrote in
message news:[hidden email]...
>I am using ReStore with a 109 MB Access database.  ReStore uses an ODBC
>DBConnection under the hood.  I am trying to optimize a reporting task.  It
>involves retrieving some composite objects from the database and combining
>them (one could think of it like summing).  When I use my existing ReStore
>code there are periods of time where things seem to come to a standstill
>during processing, taking much longer than I would expect.  When I tried to
...

Bill and Chris, thanks for the feedback on this issue.  I have not figured
out what was going on yet, but I managed to dodge the issue by compacting
the database, it went from 109 MB to 15 MB.  Apparently the user imported
and deleted a whole lot of records.  I will now be adding automatic
compaction support.

Chris