[squeak-dev] Re: MessageTally problems
Igor Stasenko
siguctua at gmail.com
Fri Apr 23 03:49:34 UTC 2010
On 23 April 2010 04:42, Andreas Raab <andreas.raab at gmx.de> wrote:
> 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.
>
Andreas, for me, it feels like this whole post deserves to be found in
HelpSystem! :)
> 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
>>
>>
>
>
>
--
Best regards,
Igor Stasenko AKA sig.
More information about the Squeak-dev
mailing list
|