On Wed, 9 Jan 2013, Colin Putney 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.)
> 
> Anybody have any ideas for how to get a better profile?

Qwaq made two profilers, one for the VM and one for the image. The 
latter's port for Pharo can be found here: 
http://www.squeaksource.com/SystemProfilerPharo.html
(IIRC it loads into Squeak too.)

It uses some primitives which were added to the CogVM, so it requires Cog. 
We could reimplement it from scratch using the same primitives and 
get a better profiler in the image. We can't include this due to the GPL 
license.


Levente

> 
> Colin
> 
>