Problem measuring code execution time !

[Kevin Urben]

I have a weird problem - I don't know if anyone can help !

I am trying to time how long it takes for a procedure called "Recalculate"
to execute. So I created a button on a form and hooked up this OnClick
method:

procedure TMainForm.TestBtnClick(Sender: TObject);
var
i : Integer;
t1 : DWORD;
t2 : DWORD;
t : Single;

begin
TestBtn.Caption:='WAIT ...';
Application.ProcessMessages;

t1:=GetTickCount;
for i:=1 to 100 do
begin
Recalculate;
Application.ProcessMessages;
end;
t2:=GetTickCount;
t:=(t2-t1)/100;
TestBtn.Caption:=Format('%.1f ms', [t]);
end;

As you can see, the procedure just calls Recalculate 100 times, and displays
the average execution time on the button.

Here's the weird thing: if the button has the focus, and I activate it using
the spacebar or enter, then t=35 ms.
But if I click the button with the mouse, t=63 ms - nearly twice slow !!

These two times are absolutely repeatable and reliable.

I am using Windows XP Professional with Intel Core 2 Duo (2MHz). No other
processes are running which are taking up significant CPU time. When the
test loop runs, CPU usage maxes out at 50% in both cases. The PF delta
figure maxes out at about 300 when the code runs slowly, and 550 when
running quickly. (I thought more PF's would give me a slower time).

None of this makes any sense to me - why should execution time depend on how
the button was pressed ?!

By the way, Recalculate does a lot of floating-point stuff - I don't know if
this is relevant.

Any help would be very much appreciated - I am begining to lose sleep over
this one !

Kevin

[alang...@aol.com]

On 31 May, 16:32, "Kevin Urben" <m...@nospam.co.uk> wrote:
<snip>

> Any help would be very much appreciated - I am begining to lose sleep over
> this one !
>

Do you know what messages are being sent to your application when the
multi-calculation loop is running - No you don't. And any of those
messages could use a chunk of processor time.

Take the Application.ProcessMessages out of your code - why do you
think its needed there ?

Alan Lloyd

[alang...@aol.com]

AND DON'T MULTI-POST

Alan Lloyd

[Kevin Urben]

Thanks for your comment.
Execution time is the same with or without Application.ProcessMessages.
Sorry - I meant to mention that.
Recalculate ends by displaying some results on screen. I put
Application.ProcessMessages in there to allow screen updates but actually
it's not needed.

Kevin

[Kevin Urben]

... and don't shout - I can hear perfectly well.

I am trying to make a serious and polite request for help - if you do not
like the way I do it please explain why. I cross-posted to 3 groups in the
hope more people would see my post - what is the problem with that ? Why
should I make 3 separate posts ?

<alang...@aol.com> wrote in message
news:a5a63133-6de5-4af5...@x41g2000hsb.googlegroups.com...

[Jamie]

Kevin Urben wrote:

Windblows does preemptive tasking.

It's very difficult to get a perfect execution
time on your piece of code.
Using the GetTick function is a basic approach as you
did how ever. since Windows pre-empts the task on a time
slice. You're code is getting caught in a break time because
of the difference between the methods used to get your code
executed.
Mouse activity involves more processing, this processing chews
up your slice time how ever, this factor is not constant because it
just happens to be where your code gets executed in the time slice.

What you could try is to perform a SLEEP(0) just prior your code
execution.
This should force an end to the slice for the current thread and when
it returns start you a new one..
Just an idea.

http://webpages.charter.net/jamie_5"

[Skybuck Flying]

My guess is when you hold the mouse cursor over something or move it then
windows does extra processing to determine for example if it should display
hints or other cursor icons or stuff like that.

Maybe you should try a console application and test there...

Or post your recalculate code so we can take a look at it... maybe you doing
something weird in there ;)

Bye,
Skybuck.

[Kevin Urben]

Thanks for your suggestion, Jamie. I was not aware of the Sleep() function.

I have tried Sleep(0) before the first t1:=GetTickCount; No change in the
times.
I also tried Sleep(1000) and Sleep(5000) - to allow time for any short-term
threads started by the mouse click to finish.
Again - no change in the times !

[Jamie]

Kevin Urben wrote:

> Thanks for your suggestion, Jamie. I was not aware of the Sleep() function.
>
> I have tried Sleep(0) before the first t1:=GetTickCount; No change in the
> times.
> I also tried Sleep(1000) and Sleep(5000) - to allow time for any short-term
> threads started by the mouse click to finish.
> Again - no change in the times !

Actually what you did was defeat it.
sleep just swings out to another thread or another task, any thing
left in your process does not get processed!.. when it comes back, it
still waiting..
If you want to make sure most of the messages are done in your que .
then do a loop using PeekMessage but not remove anything and call the
Application.ProcessMessages unitl you get nothing more than maybe a
WM_IDL or what ever they call it..
form there, you then call Sleep(0); not any other value.
then get the Tick count and start your code.

http://webpages.charter.net/jamie_5"

[Kevin Urben]

OK - this is getting weirder ! I changed the code as you suggested:

procedure TMainForm.TestBtnClick(Sender: TObject);
var
i : Integer;
t1 : DWORD;
t2 : DWORD;
t : Single;

Msg : TMsg;

begin
TestBtn.Caption:='WAIT ...';

// SetThreadPriority(GetCurrentThread, THREAD_PRIORITY_HIGHEST);

while PeekMessage(Msg, MainForm.Handle, 0, 0, PM_NOREMOVE) do
Application.ProcessMessages;
Sleep(0);

t1:=GetTickCount;
for i:=1 to 100 do
begin
Recalculate;

// Application.ProcessMessages;

end;
t2:=GetTickCount;
t:=(t2-t1)/100;

TestBtn.Caption:=Format('%.1f ms', [t]);
end;

Now the timings are exactly reversed - clicking the button gives t=35 ms,
pushing the button gives t=63 ms !!

As you can seem I also tried

SetThreadPriority(GetCurrentThread, THREAD_PRIORITY_HIGHEST);

before the timing loop - no difference !

Skybuck:

Thanks for that suggestion. I move the mouse away from the button after the
click - and the Sleep() command I tried should have let things settle before
the timing loop begins (I think).
Unfortunately, Recalculate() contains many nested procedures - there's
dozens of pages of code in there - so not practical to post it !

Thanks again everyone for your suggestions.

[Jim P]

clearly you do not hear very well.

One post is all that it takes to get a response - -
many people that scan this newsgroup also scan the others.
and thus you force them to read the same post on the same subject again

and you should make only one post - - - out of respect to those that
are willing to help you. - - -

if you do not want to follow this guideline - - then the experts will
not be as willing to help you - - - -

Understand - - it is called respect.

Jim P.

[Kevin Urben]

But - now if I delete:

while PeekMessage(Msg, MainForm.Handle, 0, 0, PM_NOREMOVE) do
Application.ProcessMessages;
Sleep(0);

the timings stay switched over !

Obviously there are, for some reason, two speeds at which this code runs,
and making apparently innocent changes can cause it to flip from one state
to the other. I am still baffled !

[Hans-Peter Diettrich]

Kevin Urben schrieb:

> I am trying to time how long it takes for a procedure called "Recalculate"
> to execute. So I created a button on a form and hooked up this OnClick
> method:

...
> t1:=GetTickCount;

What's the granularity of TickCount? What if you use Now() instead?

DoDi

[alang...@aol.com]

I have used QueryPerformanceTimer successfully to time events. I wrote
a unit as below. See if it works for you better than TickCount.

unit QPTimerU;

interface

uses
Windows ;

type
TTimeType = (ttSecs, ttMilliSecs, ttMicroSecs);

procedure StartPeriod;
procedure EndPeriod;
function ScaleTime(TimeSecs : double; TimeType : TTimeType) : double;

var
ElapsedCount : DWord;
ElapsedTime : double;

implementation

var
TempQPC, QPF, StartQPC : TLargeInteger;
OverHeadCount : extended;

function LargeIntToExt(LI : TLargeInteger) : extended;
const
Num : extended = $10000;
begin
{$IFDEF VER100}
Result := (LI.HighPart * Num * Num) + LI.LowPart; // Delphi 3
{$ELSE}
Result := (LARGE_INTEGER(LI).HighPart * $10000 * $10000) +
LARGE_INTEGER(LI).LowPart;
{$ENDIF}
end;

function ScaleTime(TimeSecs : double; TimeType : TTimeType) : double;
begin
Result := TimeSecs;
while TimeType > ttSecs do begin
Result := Result * 1000;
dec(TimeType);
end;
end;

procedure StartPeriod;
begin
QueryPerformanceCounter(StartQPC); // for overhead calc
QueryPerformanceCounter(TempQPC);
OverHeadCount := LargeIntToExt(TempQPC) - LargeIntToExt(StartQPC);
QueryPerformanceCounter(StartQPC); // real start time
end;

procedure EndPeriod;
var
EndQPC : TLargeInteger;
EndCount : extended;
StartCount : extended;
begin
QueryPerformanceCounter(EndQPC);
EndCount := LargeIntToExt(EndQPC);
StartCount := LargeIntToExt(StartQPC);
ElapsedCount := trunc(EndCount - StartCount - OverHeadCount);
QueryPerformanceFrequency(QPF);
ElapsedTime := ElapsedCount / LargeIntToExt(QPF);
end;

(*
// / / / / / / / / / / / /
// U s a g e
// / / / / / / / / / / / /

uses
QPTimerU;

procedure TForm1.StartBtnClick(Sender: TObject);
begin
StartPeriod;
end;

procedure TForm1.StopBtnClick(Sender: TObject);
begin
EndPeriod;
Label1.Caption := Format('%d counts', [ElapsedCount]);
Label2.Caption := Format('%6f secs', [ScaleTime(ElapsedTime,
ttSecs)]);
Label3.Caption := Format('%3f millisecs', [ScaleTime(ElapsedTime,
ttMilliSecs)]);
Label4.Caption := Format('%d microsecs',
[trunc(ScaleTime(ElapsedTime, ttMicroSecs))]);
end;
*)
end.

Alan Lloyd

[Kevin Urben]

GetTickCount() returns milliseconds, but the granularity is about 10ms, I
think.

However, the time I am measuring is about 3.5 secs, or 7.0 secs, so small
errors of 10 ms are not serious. I've tried increasing the loop count, to
increase the elapsed time, with no change in the average time.

"Hans-Peter Diettrich" <DrDiet...@aol.com> wrote in message
news:6adnrbF...@mid.individual.net...

[Dr J R Stockton]

In alt.comp.lang.borland-delphi,borland.public.delphi.language.objectpas
cal,comp.lang.pascal.delphi.misc message <DYqdnancofIKBNzVnZ2dnUVZ_g-
dn...@comcast.com>, Sat, 31 May 2008 11:31:48, Jim P
<Ji...@mad.scientist.com> posted:

>Kevin Urben wrote:
>> ... and don't shout - I can hear perfectly well.
>> I am trying to make a serious and polite request for help - if you
>>do not
>> like the way I do it please explain why. I cross-posted to 3 groups
>>in the hope more people would see my post - what is the problem with
>>that ? Why should I make 3 separate posts ?
>> <alang...@aol.com> wrote in message
>> news:a5a63133-6de5-4af5...@x41g2000hsb.googlegroups.com...
>>> AND DON'T MULTI-POST
>>>
>>> Alan Lloyd

I would have expected you to know the difference between cross- and
multi- posting. This is certainly a cross-post, and I have not as yet
noticed any multi.

>clearly you do not hear very well.
>
>One post is all that it takes to get a response - -
>many people that scan this newsgroup also scan the others.
>and thus you force them to read the same post on the same subject again
>
>and you should make only one post - - - out of respect to those that
>are willing to help you. - - -
>
>if you do not want to follow this guideline - - then the experts will
>not be as willing to help you - - - -
>
>Understand - - it is called respect.

If *you* were to understand, you might start gaining respect.

>Jim P.

This article has been cross-posted to three groups, in the alt, borland,
and comp hierarchies.

Hierarchy news:borland.* belongs to Borland, and should only be
accessed, or at least only written to, using the Borland servers; it
leaks out to the general Usenet servers, but does not leak in.
Therefore the experts do not see articles posted to Usenet servers. By
the way, Borland ban cross- as well as multi- posting - unwisely, but
they have the right to do so -- but in this case, they will not care,
unless anyone replies into their servers without de-cross-posting.

Cross-posting to a small number of relevant Usenet newsgroups is
perfectly acceptable; the OP should not have cross-posted to Borland.

Of course, since Borland do not say that in their newsgroups, there's no
obvious way for the OP to discover that. But, if he does not get a good
reply here, he should re-post to the most appropriate Borland group,
using a Borland server (e.g. forums.borland.com).

If you don't know the difference between cross- and multi- posting, ask
Wilipedia about the former.

If your newsreader does not, in all its newsgroups, mark an article as
read when it is read in one group, then you have it mis-configured or
have made a bad choice. Remedy that yourself.

IMHO, for reliable timing, the OP should use intervals substantially
longer than about 50 ms; and should not have Application.ProcessMessages
within the timed loop. And should know that, while (AFAIR; see my site)
getTickCount can show any number of milliseconds, it may not be updated
every millisecond, depending on system. QueryPerformanceCounter could
be better.

ISTM that the OP may be detecting the time taken to draw the button
going in & out.

--
(c) John Stockton, nr London UK. ?@merlyn.demon.co.uk BP7, Delphi 3 & 2006.
<URL:http://www.merlyn.demon.co.uk/> TP/BP/Delphi/&c., FAQqy topics & links;
<URL:http://www.bancoems.com/CompLangPascalDelphiMisc-MiniFAQ.htm> clpdmFAQ;
<URL:http://www.borland.com/newsgroups/guide.html> news:borland.* Guidelines

[JohnH4]

> I am trying to time how long it takes for a procedure called "Recalculate"
> to execute. So I created a button on a form and hooked up this OnClick
> method:

Kevin,
Why don't you use the TSC (the CPU's cycle counter) to time you code?
Regards, JohnH

[Nicholas Sherlock]

Kevin Urben wrote:

> Here's the weird thing: if the button has the focus, and I activate it using
> the spacebar or enter, then t=35 ms.
> But if I click the button with the mouse, t=63 ms - nearly twice slow !!

Do you have a CPU which scales its clock speed based on system load?
They're common in laptop computers.

Cheers,
Nicholas Sherlock

[Kevin Urben]

Thanks very much for your suggestion.

I am using a Dell Latitude D830 laptop with Intel Core 2 Duo T7300 and 2MHz
clock. I have just checked on the web and noted it has speedstep
technology - this could be something ! I was foolishly thinking the new Core
2's were so power efficient they didn't need it - oops.

I did try running the program on my old Pentium 4 laptop with
speedstep - on that I have a utility to enable/disable speedstep.
I still get a time difference on that laptop - but it is a little
less.marked (42ms vs. 55ms) compared with the newer laptop (35ms vs 63ms).
The times were the same whether speedstep was enabled or not - I guess
speedstep reacts quickly to load and ran the bulk of my benchmark at maximum
speed.

Does anyone know how speedstep works on my new laptop ? I'll try and find
out myself tomorrow when I have some more time, and install the speedstep
utility. I suppose speedstep would be neat explanation of why I get two
distinct run times - and nothing in between ..

Thanks again, Kevin

"Nicholas Sherlock" <N.she...@gmail.com> wrote in message
news:dc409ba7-d7d6-42e8...@a32g2000prf.googlegroups.com...