On Jul 26, 2007, at 2:40 PM, Adrian Lienhard wrote:

> Let's see. This is an excerpt from the very beginning of the trace,  
> showing one UI cycle. No other process was active in this period.
> The numbers indicate: proc, ctxt, statIncrGCs, statTenures,  
> statFullGCs, ioMSecs
>
>
> 1145108440 1189307120 58988 5419 106 796524  
> WorldState>interCyclePause:
> ....
> 1145108440 1189307696 58988 5419 106 796524  
> EventSensor>nextEventFromQueue
> 1145108440 1189302556 58989 5419 106 796531 SharedQueue>isEmpty
> ....
> 1145108440 1189304704 58989 5419 106 796537  
> UserInputEvent>transformedBy:
> 1145108440 1189304084 58990 5419 106 796544  
> UserInputEvent>transformedBy:
> ....
> 1145108440 1189307680 58990 5419 106 796547  
> HandMorph>noticeMouseOver:event:
> 1145108440 1189303900 58991 5419 106 796555  
> MouseOverHandler>noticeMouseOver:event:
> ...
> 1145108440 1189307120 58991 5419 106 796556  
> WorldState>interCyclePause:
>
> - The elapsed time between the start and end of the cycle is 796556  
> - 796524 = 32
> - There has been 3 IGCs consuming: 7 + 7 + 8 = 22

Keep in mind of course logging message sends *is* expensive and will  
make things *lots* slower.
I'd have to look but the IGC ms clock times are recorded in the VM,  
before/after the GC work so any logging would not interferr
with that data
--
======================================================================== 
===
John M. McIntosh <johnmci at smalltalkconsulting.com>
Corporate Smalltalk Consulting Ltd.  http://www.smalltalkconsulting.com
======================================================================== 
===