Subject | Mysterious performance problem |
---|---|
Author | Geoff Worboys |
Post date | 2015-01-23T08:17:50Z |
Hi Jason, and anyone else with guess at this problem,
I have an old application recently upgraded from FB v1.5 and
IBO v4.8, to FB v2.5 and IBO v5. It is still being compiled
using Delphi6 (may be important), the migration to a newer
Delphi is still on the to-do list. (Using 32bit Firebird
server, but I think FB is irrelevant to this, see below.)
The application works smoothly here in development, with the
server running on a 32bit XP Pro workstation, and the client
running anywhere from that "server" to 64bit Win8 Pro and
Server 2012 systems.
BUT, in at a client things are strange, with odd performance
problems.
The most predictable place that I see a problem is when I close
certain forms. The ib_monitor log below was taken after closing
a form from search mode, without ever having gone to browse so
there are no data clean-up issues to consider. (It happens
whether in search or browse, but just trying to keep it as
simple as possible - so for this example there were no blobs
loaded by the dataset or anything complicated like that.)
It happens on multiple forms, but this example has a master
"DetailDQ" and a detail "LogDQ" (and some others but it doesn't
matter whether they are active or not, the problem always
occurs around LogDQ).
LogDQ is pretty simple, there are only 16 fields, only one
blob. It takes 0.001s to prepare.
I hacked IB_Monitor a bit to show me "Interval" values - seconds
between each message written to the log, obtained using the high
performance counter APIs, so they're accurate even to small times.
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._currentcursor_.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._currentcursor_.SysDeallocate(End)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._buffercursor_.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._buffercursor_.SysDeallocate(End)
====*/
/*---
[ 2015-01-23 17:15:24 (Interval: 1.030s) ] <<<<< SEE NOTE-1 !!!!!
DEALLOCATE STATEMENT
STMT_HANDLE = 599
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
----*/
/*===
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ.SysDeallocate(End)
====*/
/*===
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
<parent>.DataModule.DetailDQ.SysDeallocate(Begin)
====*/
NOTE-1: The highlighted line above shows that there was more
than one whole second between the prior SysDeallocate(End) call
for the internal LogDQ._buffercursor_, and starting the actual
deallocate API call of LogDQ.
This is the only place (on this form) where this happens, and
only at the client installation, not here. If I have other
child/detail datasets activated they go through this same code
without delay.
The client's 32bit Firebird v2.5.3 server is running on a 64bit
Win2012 server (but I've also run it on a 32bit Win2003 server
with the same problem - these are all virtual machines, as are
all my systems here). (Note: A 64bit Win2012 server needs
special registry entries to let you run old Delphi apps, to work
around exception handling changes, but these are set and were
working with the previous version of this same application).
BUT, the ib_monitor log above would appear to prove that the FB
server is not relevant to this problem, the delay appears to
be somewhere inside my client application.
The client applications, at this client, are all running under
terminal server sessions. This is, perhaps, the main distinction
between the client and here, but I've never had terminal server
issues of this nature with the old version. Anyway, I set up
my Win8 machine to receive remote connections and tested, the
same chunk of code takes less than 1ms.
I'm guessing the next step is to set up a whole lot of tracking
inside the code to see if I can find which line is causing the
problem (I'm thinking IB_monitor could be very useful to me for
this - it's a great thing to have, Jason!) ... but first I
thought I'd see if anyone had any suggestions on what might
cause this sort of problem.
--
Geoff Worboys
Telesis Computing Pty Ltd
I have an old application recently upgraded from FB v1.5 and
IBO v4.8, to FB v2.5 and IBO v5. It is still being compiled
using Delphi6 (may be important), the migration to a newer
Delphi is still on the to-do list. (Using 32bit Firebird
server, but I think FB is irrelevant to this, see below.)
The application works smoothly here in development, with the
server running on a 32bit XP Pro workstation, and the client
running anywhere from that "server" to 64bit Win8 Pro and
Server 2012 systems.
BUT, in at a client things are strange, with odd performance
problems.
The most predictable place that I see a problem is when I close
certain forms. The ib_monitor log below was taken after closing
a form from search mode, without ever having gone to browse so
there are no data clean-up issues to consider. (It happens
whether in search or browse, but just trying to keep it as
simple as possible - so for this example there were no blobs
loaded by the dataset or anything complicated like that.)
It happens on multiple forms, but this example has a master
"DetailDQ" and a detail "LogDQ" (and some others but it doesn't
matter whether they are active or not, the problem always
occurs around LogDQ).
LogDQ is pretty simple, there are only 16 fields, only one
blob. It takes 0.001s to prepare.
I hacked IB_Monitor a bit to show me "Interval" values - seconds
between each message written to the log, obtained using the high
performance counter APIs, so they're accurate even to small times.
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._currentcursor_.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._currentcursor_.SysDeallocate(End)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._buffercursor_.SysDeallocate(Begin)
====*/
/*===
[ 2015-01-23 17:15:23 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ._buffercursor_.SysDeallocate(End)
====*/
/*---
[ 2015-01-23 17:15:24 (Interval: 1.030s) ] <<<<< SEE NOTE-1 !!!!!
DEALLOCATE STATEMENT
STMT_HANDLE = 599
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
----*/
/*===
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
<parent>.DataModule.LogDQ.SysDeallocate(End)
====*/
/*===
[ 2015-01-23 17:15:24 (Interval: 0.000s) ]
<parent>.DataModule.DetailDQ.SysDeallocate(Begin)
====*/
NOTE-1: The highlighted line above shows that there was more
than one whole second between the prior SysDeallocate(End) call
for the internal LogDQ._buffercursor_, and starting the actual
deallocate API call of LogDQ.
This is the only place (on this form) where this happens, and
only at the client installation, not here. If I have other
child/detail datasets activated they go through this same code
without delay.
The client's 32bit Firebird v2.5.3 server is running on a 64bit
Win2012 server (but I've also run it on a 32bit Win2003 server
with the same problem - these are all virtual machines, as are
all my systems here). (Note: A 64bit Win2012 server needs
special registry entries to let you run old Delphi apps, to work
around exception handling changes, but these are set and were
working with the previous version of this same application).
BUT, the ib_monitor log above would appear to prove that the FB
server is not relevant to this problem, the delay appears to
be somewhere inside my client application.
The client applications, at this client, are all running under
terminal server sessions. This is, perhaps, the main distinction
between the client and here, but I've never had terminal server
issues of this nature with the old version. Anyway, I set up
my Win8 machine to receive remote connections and tested, the
same chunk of code takes less than 1ms.
I'm guessing the next step is to set up a whole lot of tracking
inside the code to see if I can find which line is causing the
problem (I'm thinking IB_monitor could be very useful to me for
this - it's a great thing to have, Jason!) ... but first I
thought I'd see if anyone had any suggestions on what might
cause this sort of problem.
--
Geoff Worboys
Telesis Computing Pty Ltd