[squeak-dev] Re: MessageTally problems

Andreas Raab andreas.raab at gmx.de
Fri Apr 23 01:42:39 UTC 2010


See the discussion here:

http://lists.squeakfoundation.org/pipermail/squeak-dev/2009-February/134405.html

What you're seeing is issue #3 in the above post.

Cheers,
   - Andreas

On 4/22/2010 6:29 PM, Chris Muller wrote:
> I am trying to do a very heavy lifting task with Squeak, but it is
> taking longer than I think it should.  So of course, I used the
> profiler, but I just can't make any sense of it.  I profiled a huge
> operation that took a couple of hours.  To do the profile I used:
>
>    MessageTally spyAllOn: [ ... my big operation... ]
>
> According to the profile, only 46% of the time was spent doing
> anything related to MY stuff, but with 41% of it being in
> "primitives"!
>
> 46.0% {9799162ms} MauiWorld class>>maui:
>    46.0% {9799162ms} MauiFamily>>newViewNamed:for:
>                          <--- snip ---->
>
>           |      41.2% {8776640ms}
> MaFixedObjectBuffer(MaObjectBuffer)>>oid
>
>           |        41.2% {8776640ms} primitives
>
> The snipped portion is all my code, zooming down a single tree branch
> straight to "primitives".  Does this mean the Smalltalk is optimized
> to consuming only 5% of the total of everything?
>
> The other 53.9% was spent, here:
>
> --------------------------------
> Process: (60) 10116: [] in Delay>>wait
> --------------------------------
> 53.9% {11482061ms} EventSensor>>eventTickler
>    50.5% {10757775ms} Delay>>wait
>      |50.5% {10757775ms} primitives
>    2.5% {532563ms} primitives
>
> What is this??
>
> Is it possible there is something wrong with the profiler?  From the
> section of the report about garbage-collection, it would appear so:
>
> ---------------------------------------------
> **Leaves**
> 50.6% {10779078ms} Delay>>wait
> 41.2% {8776640ms} MaByteObjectBuffer(MaObjectBuffer)>>oid
> 2.5% {532563ms} EventSensor>>eventTickler
>
> **Memory**
> 	old			+105,090,944 bytes
> 	young		+141,708 bytes
> 	used		+105,232,652 bytes
> 	free		+48,992 bytes
>
> **GCs**
> 	full			34 totalling 20,612,579ms (97.0% uptime), avg 606252.0ms
> 	incr		703603 totalling 18446744070288121880 milliSeconds ms
> (8.6594166983905e13% uptime), avg 2.6217546073977e13ms
> 	tenures		2,429 (avg 289 GCs/tenure)
> 	root table	0 overflows
> ----------------------------------------------
>
> As interesting as
>
> Check out the time for incremental GC's..  Yes, that really is
> eighteen quintillion, four hundred forty-six quadrillion, seven
> hundred forty-four trillion, seventy billion, two hundred eighty-eight
> million, one hundred twenty-one thousand, eight hundred eighty
> milliseconds spent doing incremental GC's.  That can't be right...
> :)
>
> Wait, there's more.
>
> After profiling my operation, the image is just sitting there with the
> Spy Results, but the vm was consuming nearly 100% of the CPU.  I do
> not think this was the sound issue because I have that preference set
> to stop playing, and also that the utilization was not so pegged but
> dipping down to 95% a bit, I think.
>
> My question:  What the hell is Squeak doing?
>
> Again, I try to call upon MessageTally for the answer:
>
>        MessageTally spyAllOn: [ (Delay forSeconds: 30) wait ]
>
> What do I get?  Nada!  (pasted below).
>
> I have a deadline pressing and I'm really stuck on this!  The profiler
> is an absolutely _essential_ tool.  Is my code the problem or is there
> a problem with Squeak?
>
> Thank you for any insights!
>     - Chris
>
> "Nada"
>   - 29927 tallies, 30016 msec.
>
> **Tree**
> --------------------------------
> Process: (60) 23304: [] in Delay>>wait
> --------------------------------
> 5.4% {1621ms} EventSensor>>eventTickler
>    5.4% {1621ms} Delay>>wait
>      5.4% {1621ms} primitives
> --------------------------------
> Process: (10) 20578: ProcessorScheduler class>>idleProcess
> --------------------------------
> 94.4% {28335ms} ProcessorScheduler class>>idleProcess
> 
> **Leaves**
> 94.4% {28335ms} ProcessorScheduler class>>idleProcess
> 5.5% {1651ms} Delay>>wait
>
> **Memory**
> 	old			+0 bytes
> 	young		-331,640 bytes
> 	used		-331,640 bytes
> 	free		+331,640 bytes
>
> **GCs**
> 	full			0 totalling 0ms (0.0% uptime)
> 	incr		8 totalling 10,843ms (36.0% uptime), avg 1355.0ms
> 	tenures		0
> 	root table	0 overflows
>
>




More information about the Squeak-dev mailing list