[2] [gclist] GC & profiling

eliot@parcplace.com eliot@parcplace.com
Mon, 23 Apr 2001 09:28:42 -0700


-covering message-

+-----------------------------
| Date:	Mon, 23 Apr 2001 00:11:54 +1000
| From:	Fergus Henderson <fjh@cs.mu.oz.au>
| Subject:	Re: [gclist] GC & profiling

| On 19-Apr-2001, eliot@parcplace.com <eliot@parcplace.com> wrote:
| > Fergus Henderson <fjh@cs.mu.oz.au>:
| > | For accurate profiling of execution time, GC can cause some problems,
| > | because GCs can occur at semi-random times, but the blame for time
spent
| > | in a GC should really be spread among all the routines that allocated
| > | the memory, not on the routine that happened to do the final memory
| > | allocation which triggered that GC.  If you don't treat GC specially,
| > | then some innocuous routine can be unfairly blamed for a large
proportion
| > | of the execution time simply because that routine happened to be the
| > | one that triggered a collection.
| >
| > | On the other hand, costs of ordinary memory allocation should indeed be
| > | credited to the calling routine.
| >
| > I'm not sure if this is the best way iof solving it, but it is an
alternative
| > approach.  The VisualWorks Smalltalk profiling facilities provide both a
time
| > profiler and an allocation profiler.  The time profiler doesn't include
| > explicit GC time.  Instead it is simply a statistical sampler of
Smalltalk
| > methods, so GC time is hidden.

| I'm not sure what you mean by that.
| Do you mean that
| 	- if a profiling timer tick occurs during GC, that tick is discarded?
| 	- if a profiling timer tick occurs during GC, that tick is credited to
| 	  the currently active Smalltalk method?
| 	  (This is what happens in the current Mercury profiler.)
| 	- profiling ticks can never occur during GC (e.g. because the
| 	  profiler actually counts number of bytecode instructions executed,
| 	  rather than time)?
| 	- something else?

Option 2,  if a profiling timer tick occurs during GC, that tick is credited
to the currently active Smalltalk method, which means GC costs are effectively
hidden.

Getting slightly off-topic, the only wrinkle (which is an interesting one) is
that the profiling tick is not a special VM level event.  Instead, time
profiling is done by a high-priority Smalltalk process that loops waiting on a
delay and then sampling the PC of the lower-priority profiled process.  This
means the profiling process can contribute to GC overhead as it does
allocation in its analysis of the profiled process's stack.  Currently we use
a recursive algorithm to walk the profiled process's stack and that's a bug
because profiling deep call stacks introduces large overheads.  For debugging
reasons we refuse to do tail recursion elimination.  So we're rewriting to use
explicit iteration.

---
Eliot Miranda                ,,,^..^,,,
mailto:eliot@parcplace.com
VisualWorks Engineering, Cincom    Smalltalk: scene not herd Tel +1 408 216
4581
3350 Scott Boulevard, Building 36, Santa Clara, CA 95054 USA Fax +1 408 216
4500