[Vm-dev] Profiling and delay accuracy

[David T. Lewis]

I need to ask some guidance. The problem that Andreas describes below has
been left unresolved for an embarassingly long time, so I would like to
bring some closure to it. Unfortunately I'm not an expert here, so I need
to ask advice.

The problem is tracked on Mantis here:
  http://bugs.squeak.org/view.php?id=7653

And I think that this one is basically the same issue:
  http://bugs.squeak.org/view.php?id=7515

I have tried three different approaches to fixing this:

1) Re-apply the logic from Andreas' original version of primitiveResponse
(stamped 'ar 2/20/2001). I looked at the old 2001 version and merged that
timer check logic into the current primitiveResponse.

2) Add a call to checkForInterrupts in primitiveResponse. This is just adding
a 'self checkForInterrupts' before leaving the primitiveResponse method.

3) Add a call to quickCheckForInterrupts in primitiveResponse. Same as above,
but call quickCheckForInterrupts, which reduces the number of times that
checkForInterrupts gets called.

None of these changes seems to result in significant performance reductions
that I could measure. Option 2 (add primitiveResponse) seems to be most
beneficial in terms of TimeProfileBrowser (but I am uncertain of this).

My concern would be that I am testing with a slow interpreter and relatively
fast hardware, so the performance characteristics might be quite different
when running on a slow machine or when running under Cog.

Any advice would be welcome. If there are no objections or further comment,
I'll update the trunk VMMaker with the second option (add checkForInterrupts).

Thanks,
Dave

On Thu, Jun 14, 2007 at 09:21:59PM -0700, Andreas Raab wrote:
> 
> Hi Folks -
> 
> For a long time now I had this feeling that MessageTally reports pretty 
> bogus results in many situations without being able to precisely track 
> down why this would be the case. Today I was looking at 
> primitiveResponse() and, much to my surprise, noticed that the 
> checkForInterrupts() that used to be there for years is gone (see 
> Squeak3.6 for example which still has it). The sole reason for this 
> check was to get both high delay accuracy and good profiling behavior. 
> Consider this example:
> 
> fc := FormCanvas on: Display.
> MessageTally spyOn:[
> 	1 to: 100 do:[:i|
> 		fc fillColor: Color white.
> 		fc printString.
> 	].
> ].
> 
> Using 3.6 this will be measured correctly as:
> 
> **Tree**
> 87.5% {243ms} FormCanvas>>fillColor:
>   |87.5% {243ms} GrafPort>>fillRect:offset:
>   |  87.5% {243ms} GrafPort>>copyBits
> 12.5% {35ms} FormCanvas(Object)>>printString
>   12.5% {35ms} FormCanvas(Object)>>printStringLimitedTo:
> 
> whereas the 3.10 reports it as
> 
> **Tree**
> 99.6% {670ms} FormCanvas(Object)>>printString
>   94.9% {639ms} primitives
>   4.6% {31ms} FormCanvas(Object)>>printStringLimitedTo:
> 
> I think you can see the problem and just imagine what this does to any 
> cumulative results. I also wonder what that change does to platforms 
> that don't have high-resolution asynchronous timers. This used to be the 
> one place where we would catch timer changes at high resolution and 
> unless the platform forces high resolution timer interrupts 
> asynchronously (by resetting the interrupt counter) we must be loosing a 
> lot in terms of delay accuracy. (it just so happens that the Windows VM 
> *does* do asynchronous timer interrupts so I never noticed this but I'm 
> very curious about the difference on Linux which typically still has 
> pretty bad timer granularity).
> 
> Any opinions? My feeling is that the timer check should go back in for 
> all of the above reasons. At the very least a quickCheckForInterrupt() 
> is required but I actually think putting the full check back in is worth it.
> 
> Cheers,
>   - Andreas