Profiling?

In a PasteUpMorph I have tenth of programmed Morph shapes (line, cicle,
polyline), and it starts to get slow. I need to collect some profiling
data to optimise the code.

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

Are there alternative tools for profiling?

Hilaire




--
ADD R0,R1,R2,LSL #2

Hello Hilaire,

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.

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:[hidden email]

> 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"
<[hidden email]> said:

Hello Doug,

DW> calling what.  You can improve that by editing the method MessageTally
class>>defaultMaxTabs to change the value from 18 to a larger number such
DW> as 60... this should still give you plenty of room on a 1024x768 screen.
DW>  (I just added this tip to the TimeProfileBrowser page on the swiki.)

Thank you. The more smalltalkish my programming gets (short methods
with long names and sadly enough many parameters to pass through to
the bottom), the more I need this. Tried your tip in one of my old
projects and it simply wasn't necessary to have deeper nesting :-))

Thanks again

Herbert                            mailto:[hidden email]