[squeak-dev] MessageTally problems

Chris Muller asqueaker at gmail.com
Fri Apr 23 01:29:58 UTC 2010


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