[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

46.0% {9799162ms} MauiWorld class>>maui:
  46.0% {9799162ms} MauiFamily>>newViewNamed:for:
                        <--- snip ---->

         |      41.2% {8776640ms}

         |        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:

50.6% {10779078ms} Delay>>wait
41.2% {8776640ms} MaByteObjectBuffer(MaObjectBuffer)>>oid
2.5% {532563ms} EventSensor>>eventTickler

	old			+105,090,944 bytes
	young		+141,708 bytes
	used		+105,232,652 bytes
	free		+48,992 bytes

	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

 - 29927 tallies, 30016 msec.

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
94.4% {28335ms} ProcessorScheduler class>>idleProcess
5.5% {1651ms} Delay>>wait

	old			+0 bytes
	young		-331,640 bytes
	used		-331,640 bytes
	free		+331,640 bytes

	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