[squeak-dev] Profiling

Eliot Miranda eliot.miranda at gmail.com
Thu Jan 10 19:08:26 UTC 2013


On Wed, Jan 9, 2013 at 8:33 PM, Colin Putney <colin at wiresong.com> wrote:

> Hi all,
>
> I'm trying to optimize some slow code, but having trouble getting a time
> profile that shows where the time is being spent. Here's the results from
> MessageTally class>>spyOn:
>
>  - 31249 tallies, 31251 msec.
>
> **Tree**
> --------------------------------
> Process: other processes
> --------------------------------
> 3.9% {1233ms} EventSensor>>eventTickler
>   3.9% {1231ms} Delay>>wait
> --------------------------------
> Process: (40s) 77070: nil
> --------------------------------
> 95.5% {29853ms} ALReadWriteTransaction(ALTransaction)>>commit:
>   95.5% {29848ms} ALReadWriteTransaction>>commit
>     94.7% {29593ms} Dictionary>>keysAndValuesDo:
>       94.7% {29593ms} Dictionary>>associationsDo:
> **Leaves**
> 94.7% {29593ms} Dictionary>>associationsDo:
> 3.9% {1231ms} Delay>>wait
>
> **Memory**
> old +891,120 bytes
>  young -273,076 bytes
> used +618,044 bytes
>  free -618,044 bytes
>
> **GCs**
> full 0 totalling 0 ms (0% uptime)
>  incr 56 totalling 28 ms (0.1% uptime), avg 0.5 ms
>  tenures 12 (avg 4 GCs/tenure)
>  root table 0 overflows
>
>
>
> Obviously, Dictionary>>associationsDo: isn't really a leaf method. I
> suspect that Cog is generating native code for the contents of the loop and
> it's not getting interrupted by the tally process. (I've tried running on
> an interpreter VM, but it fails with FFI errors, so no help there.)
>

Yes, Cog will generate native code for associationsDo: and the block its
running.  No, Cog won't prevent that block being interrupted by the tally
process.

e.g.

| count p |
count := 0.
p := [[count < 10] whileTrue: [(Delay forMilliseconds: 50) wait. count :=
count + 1]] newProcess.
p priority: Processor activePriority + 1.
p resume.
[count < 10] whileTrue: [Smalltalk globals "*" associationsDo: [:nada|]].
count

Substitute a number of blocks, e.g.

| count p |
count := 0.
p := [[count < 10] whileTrue: [(Delay forMilliseconds: 50) wait. count :=
count + 1]] newProcess.
p priority: Processor activePriority + 1.
p resume.
[count < 10] whileTrue: [Smalltalk globals associationsDo: [:nada| | i | i
:= 0. [count < 10] whileTrue: [i even ifTrue: [i := i + 1] ifFalse: [i := i
- 1]]]].
count

However, if all the associationsDo: block does is invoke a primitive then
the Squeak profiler will not produce useful info.  The default profiler
doesn't profile primitives correctly.  As others in this thread have
pointed out there;s a better profiler written by Andreas Raab, which does
profile primitives properly.

(* in 4.4 use e.g. (Smalltalk globals instVarNamed: 'contents'))


> Anybody have any ideas for how to get a better profile?
>
> Colin
>

BTW, what is the body of that block, if you can make it public?
-- 
best,
Eliot
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.squeakfoundation.org/pipermail/squeak-dev/attachments/20130110/032f6042/attachment.htm


More information about the Squeak-dev mailing list