Help with profiling some code?

Joshua 'Schwa' Gargus schwa at cc.gatech.edu
Thu May 15 22:01:05 UTC 2003


On Thu, May 15, 2003 at 11:39:18PM +0200, Andreas Raab wrote:
> 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 ;-)

Well, you could conceivably have two versions of the same plugin built
on the same day.  I don't think this is the problem, though.

> 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?

I used globals to count executions of both #tranformTransform: and
B3DRotation>>*.  They are invoked the same number of times.  

> 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.

The <primitive: > line is commented out in both images.  Is it re-enabled
in a later update? 

Well, I'll give up on this for now.  It's run as a pre-process anyway, so
I can deal with the extra wait.  Maybe it will magically fix itself :-)

Thanks,
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 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