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
|