Help with profiling some code?

Andreas Raab andreas.raab at gmx.de
Thu May 15 21:39:18 UTC 2003


Hi Josh,

Okay, so this all looks fine. BTW, Smalltalk listLoadedModules is definitive
if its sorted contents equals. E.g., you should check if
	Smalltalk listLoadedModules sort
is equal (#=) in the two images, both before and after running the code. If
it's not, check what might be different. (btw, it really should be equal if
you run the images from the same location ... and yet, you never know ;-)

But looking at the tally I was wondering about this: Is there any chance
that Transform>>transformTransform: is simply invoked much more often as it
used to? Have you tried putting in a class var or global and count it to see
if the number of invokations match up? Is there any possibility that
different code paths are taken depending on input?

If it does, then there's another thing to consider. Note the apparent
difference in the time spent in #localDirToGlobal: I know that I had a
primitive in there and (when I noticed that it was broken) disabled it.
However the primitive has been fixed in the meantime (err ... I think... ;)
but depending on whether it's on or off it might have some interesting
implications.

Cheers,
  - Andreas

> -----Original Message-----
> From: squeak-dev-bounces at lists.squeakfoundation.org 
> [mailto:squeak-dev-bounces at lists.squeakfoundation.org] On 
> Behalf Of Joshua 'Schwa' Gargus
> Sent: Thursday, May 15, 2003 11:15 PM
> To: The general-purpose Squeak developers list
> Subject: Re: Help with profiling some code?
> 
> 
> On Thu, May 15, 2003 at 11:08:27PM +0200, Andreas Raab wrote:
> > Hi Josh,
> > 
> > Couple of guesses:
> > 
> > #1: You might have some full GC issue in there. A single 
> full GC can change
> > the entire picture in the below. Make sure that there are 
> no full GCs in the
> > entire measure or else you will have to weigh in these factors.
> 
> According to the tally, there isn't.
> 
> > 
> > #2: Make sure there aren't any other processes doing wild 
> stuff while you're
> > measuring. MessageTally will attribute any time spent in 
> other processes in
> > the place that got suspended.
> > 
> 
> I'm running this from a Workspace, and I'm not spawning any 
> new processes
> myself, so this shouldn't be a problem.
> 
> > #3: Check if you're using the same combinations of VMs/plugins.
> 
> How do I check the plugins?  The results from "Smalltalk 
> listLoadedModules"
> match, but that doesn't seem definitive.  Anyway, I'm 
> launching the images
> by double-clicking in the same Windows directory, so I think 
> they're getting
> the same plugins.
> 
> Thanks for the help,
> Joshua
> 
> 
> > 
> > Cheers,
> >   - Andreas
> > 
> > > -----Original Message-----
> > > From: squeak-dev-bounces at lists.squeakfoundation.org 
> > > [mailto:squeak-dev-bounces at lists.squeakfoundation.org] On 
> > > Behalf Of Joshua 'Schwa' Gargus
> > > Sent: Thursday, May 15, 2003 10:48 PM
> > > To: Squeak Mailing List
> > > Subject: Help with profiling some code?
> > > 
> > > 
> > > Hi,
> > > 
> > > I'm having a weird performance discrepancy between code in two
> > > different images.  The code is not the same, but the the 
> part that is
> > > causing the performance hotspot should be.  Here are 
> message tallies
> > > of the weird parts:
> > > 
> > > 	|      43.1% {1162ms} Transform>>transformTransform:
> > > 	|        29.3% {790ms} B3DRotation>>*
> > > 	|          |9.0% {243ms} B3DVector3>>cross:
> > > 	|          |  |3.0% {81ms} B3DVector3>>z
> > > 	|          |  |2.4% {65ms} B3DVector3>>x
> > > 	|          |8.4% {226ms} B3DRotation class>>a:b:c:d:
> > > 	|          |  |7.2% {194ms} B3DRotation>>a:b:c:d:
> > > 	|          |  |  6.0% {162ms} B3DRotation>>normalize
> > > 	|          |  |    2.4% {65ms} B3DRotation>>b
> > > 	|          |5.4% {146ms} B3DRotation>>bcd
> > > 	|          |  |3.0% {81ms} B3DVector3 class>>x:y:z:
> > > 	|          |4.2% {113ms} B3DRotation>>a
> > > 	|        12.6% {340ms} Transform>>transformVector:
> > > 	|          6.0% {162ms} B3DRotation>>asMatrix4x4
> > > 	|          3.6% {97ms} B3DMatrix4x4>>localDirToGlobal:
> > > 	|          2.4% {65ms} B3DVector3(FloatArray)>>*=
> > > 
> > > (and the other one)
> > > 
> > > 	|        65.8% {4223ms} Transform>>transformTransform:
> > > 	|          35.4% {2272ms} B3DRotation>>*
> > > 	|            |13.6% {873ms} B3DVector3>>cross:
> > > 	|            |  |4.3% {276ms} B3DVector3 class>>x:y:z:
> > > 	|            |  |  |2.9% {186ms} primitives
> > > 	|            |  |4.1% {263ms} B3DVector3>>z
> > > 	|            |  |3.5% {225ms} B3DVector3>>x
> > > 	|            |11.3% {725ms} B3DRotation class>>a:b:c:d:
> > > 	|            |  |10.4% {667ms} B3DRotation>>a:b:c:d:
> > > 	|            |  |  9.6% {616ms} B3DRotation>>normalize
> > > 	|            |  |    2.6% {167ms} Float(Number)>>squared
> > > 	|            |3.5% {225ms} B3DRotation>>bcd
> > > 	|            |  2.9% {186ms} B3DVector3 class>>x:y:z:
> > > 	|          27.0% {1733ms} Transform>>transformVector:
> > > 	|            |14.8% {950ms} B3DRotation>>asMatrix4x4
> > > 	|            |  |4.6% {295ms} B3DRotation>>matrixClass
> > > 	|            |  |2.3% {148ms} B3DMatrix4x4>>a11:
> > > 	|            |11.0% {706ms} B3DMatrix4x4>>localDirToGlobal:
> > > 	|            |  2.6% {167ms} B3DMatrix4x4>>a31
> > > 	|            |  2.3% {148ms} B3DVector3 class>>x:y:z:
> > > 	|          2.6% {167ms} Transform>>translation:
> > > 
> > > The method Transform>>tranformTransform: is a double dispatch that
> > > you needn't concern yourself with.  The code for the method is the
> > > same in both images.  Notice that even though #* is called on 
> > > B3DRotation the same number of times (I verified this), it takes
> > > more than twice as long to run in the second image.
> > > 
> > > I decided to try to exercise just that method with the 
> following code:
> > > 
> > > | b1 b2 |
> > > b1 := B3DRotation axis: (1 at 4@3) normalized angle: 56.
> > > b2 := B3DRotation axis: (2 at 5@7) normalized angle: 22.222.
> > > [30000 timesRepeat: [b1 * b2 * b1 * b2]] timeToRun
> > > 
> > > I ran the snippet a bunch of times in both images, and they both
> > > took roughly the same time.
> > > 
> > > I tried garbage-collecting, and restarting each image.  Neither
> > > made any difference.  Does anyone have any hints about how to 
> > > approach this?
> > > 
> > > 
> > > Thanks,
> > > Joshua
> > > 
> > 
> 



More information about the Squeak-dev mailing list