Profiling?

Doug Way dway at mailcan.com
Fri Apr 7 16:50:33 UTC 2006


> HF> I have tried the MessageTally, however I don't really understand the
> HF> output and the data does not seem practical to use, I can't really see
> HF> where are the bottleneck from this data.

The output is telling you roughly what percentage of time (and total
time) is spent in each method, as you go deeper into the method call
stack.  How else would you want it displayed?

The bigger issue may be that understanding all of the Morphic event
handling code near the top is probably unfamiliar, and that can take
quite a while to figure out.  (Probably you should just ignore it.)  But
once you get down into your code (I think "DrGView" looks like your
class?), it should get a bit more familiar, since you wrote the code,
right?  (IMO MessageTally itself is pretty easy to understand.)

As far as bottlenecks go, it's hard to say because you didn't include
the entire output, but you can see that a substantial amount of time
(25%) is spent in DrGSegmentMorph>from:to:, maybe there's something that
could be optimized in there.  Although that may be a low-level method
where a lot of time would naturally be spent.  One thing you can usually
depend on is that any of your methods which do *not* appear in the
MessageTally output can be ruled out as bottlenecks.

I agree with Herbert that the "[" indenting is extremely annoying and
does make it harder to follow what is going on... which method is
calling what.  You can improve that by editing the method MessageTally
class>defaultMaxTabs to change the value from 18 to a larger number such
as 60... this should still give you plenty of room on a 1024x768 screen.
 (I just added this tip to the TimeProfileBrowser page on the swiki.)

- Doug


On Thu, 6 Apr 2006 19:53:35 +0200, "Herbert König"
<herbertkoenig at gmx.net> said:
> Hello Hilaire,
> 
> I ran into similar problems once. As far as I understand the callstack
> is sampled at certain intervals to build the analysis.
> 
> So generally if you have something that is controlled by some UI you
> will find World>>doOneCycleFor: on the top and it gets hard to
> understand. Otherwise it seems quite straightforward to me.
> On top you find what you spied on and then you find every method with
> the time spent in it.
> 
> Time for top level seems (I believe) to include the time for all sends
> which happen in this message down to the leaves.
> 
> There is an issue with primitives which are not interrupted by
> MessageTally, so they will not show up.
> 
> The [[ break the indentation, I wished this would happen less. Maybe
> it's easy to change, even for me :-))
> 
> So one thing is not to use WorldMenu, debug, start/browse MessageTally
> but to use MessageTally>>spyOn: aBlock.
> 
> This is obtained with spyOn:
>  - 2461 tallies, 2462 msec.
> 
> **Tree**
> 97.4% {2398ms} AssemblerAuswertungApp>>oldCollectEvaluateDisplay
>   |85.1% {2095ms}
>   ProduktionsDatenKommentiert>>collectCommentedPrüfRepRecords
>   |  |85.1% {2095ms}
>   ProduktionsDatenbankAnbindung>>collectComment...m:andZeitraum:
>   |  |  67.6% {1664ms}
>   ProduktionsDatenbankAnbindung>>collectComment...m:andZeitraum:
>   |  |    |67.2% {1654ms}
>   ProduktionsDatenbankAnbindung>>copyRecordsFro...o:usingSource:
>   <<-- now the culprit in the MySQL driver
>   |  |    |  62.3% {1534ms} JdmResultSet>>currentRowAsDictionary   <<-
>   <<-- solution was to use something else
>   |  |    |    |57.5% {1416ms} JdmResultSet>>valueNamed:
>   |  |    |    |  |55.8% {1374ms} JdmResultSet>>valueAt:
> 
> If I do the same profiling via the UI I get like you an endless list.
> One half happens inside HandMorph's events and the other half
> somewhere in the drawing routines.
> 
> If you have thousands of Morphs you might have problems due to the
> fact hat HandMorph spends a lot of time trying to find out to whom to
> dispatch mouse events.
> 
> This one seems the first one which is written by you.
> >> DrGDrawable(PasteUpMorph)>>processEvent:using:
> >>       |  |  |      |        |        31.6% {1168ms}
> 
> 
> HF> Are there alternative tools for profiling?
> If you have a suspicion already:
> 
> Time millisecondsToRun: [10000 timesRepeat: [yourSuspiciousMethod]]
> 
> Doug Way said in Dec2004:
> This and other performance tuning tips are on this swiki page:
> 
> http://minnow.cc.gatech.edu/squeak/1799
> 
> In 2005 Alexandre Bergel wanted to do some work on profiling, maybe he
> did something. (Brainstorming on profiling)
> 
> Anyway if you find something let me know for I'm interested too though
> I have no pressing needs right now.
> 
> I don't know much about the inner working of squeak so maybe others
> give more qualified help :-))
> 
> Cheers
> 
> Herbert                            mailto:herbertkoenig at gmx.net
> 
> 



More information about the Squeak-dev mailing list