MessageTally sometimes inaccurate? (FFI involved?)

Joshua Gargus schwa at fastmail.us
Wed Dec 22 04:49:59 UTC 2004


Hi,

I have a Croquet app that has a method #debugCheckForError that gets 
called quite often.  Depending on the application state, it might be 
called 1000 times per world cycle.  It looks something like:

debugCheckForError
    self isDebugging ifTrue: ["do some debug stuff"]

I leave out the debug stuff because 'isDebugging' is false during my 
timings.

Here's what happens when I use 'start MessageTally' from the World's 
'debug...' menu (all figures are conservative, slightly understating the 
problem).  MessageTally reports that half the time is spent in 
#debugCheckForError.  I tallied for 20 seconds, so at 1000 times/frame 
and 50 frames/second, this comes to 1000000 calls to 
#debugCheckForError.  When I compare to...

[1000000 timesRepeat: [anObject debugCheckForError]] timeToRun

...it takes roughly 800 milliseconds, more than 2 orders of magnitude 
different from what MessageTally reported.  Whuh?!?

I think that this might have something to do with proximity to FFI calls 
(for OpenGL), but don't know exactly what.  The method is typically 
called in situations like...

renderOn: ogl
    ogl
          setUp: this;
          doSomethingWith: that;
          setRenderStateUsing: theOther;
          debugCheckForError.

... where the preceding messages invoke FFI functions.

One last thing: if I give #debugCheckForError an empty method body, then 
#spyOn: no longer reports a disproportionate share of the total 
execution time.

Anyone have a clue?

Thanks,
Joshua



More information about the Squeak-dev mailing list