Also submitted under [BUG], cause I don't know about anyone else, but
profiling is what made my fixes easy. And the normal profilier seems to
error out and not report even large processes.

Try macrobenchmarks with and without this CS to see what I mean, its a
hack, cause messagetally is confusing, but it helped me..

I also include my wishlist for the future. Also, see gprof and its output
to get other ideas for useful output.

Scott


--

BTW, as a trade, can I ask a favor of someone who actually understands
MessageTally, specifically 3 enhancements.
  1. Some, maybe cleaner way of getting fine grained detail and not
have it be thrown out, like I did in my changeset.
  2. Some sort of cumulative mode, the more features below, the better.

For each function show the following: All functions it invoked directly,
and the total amount of time spent on each of those children.

(Bonus) For each function, show all the functions which invoked it, and an
estimate of the proportional amount of its runtime was as a result of
being invoked by that parent.

The leaves display doesn't accumulate the children of a function into
themselves, so Text>>addAttribute:from:to: doesn't show up strongly, even
though it and its children are hugely responsible for the cpu time.

As Text>>addAttribute:from:to: is called from something like 20-40 other
functions, The tree display masquerades its CPU time into 40 pieces.
Even now, I'm unsure how much time it and those it invokes use overall,
though I suspect that it may still be 5-20%.

-------------- next part --------------
'From Squeak3.2alpha of 3 October 2001 [latest update: #4411] on 5 October 2001 at 11:48:23 am'!

!MessageTally methodsFor: 'tallying' stamp: 'sac 9/26/2001 07:28'!
tally: context by: count 
	"Explicitly tally the specified context and its stack."
	| root |

	context method == method
		ifTrue: [^ self bumpBy: count].
	(root _ context home sender) == nil
		ifTrue: [^ (self bumpBy: count)
				tallyPath: context
				by: count].
	^ (self tally: root by: count)
		tallyPath: context
		by: count! !

!MessageTally methodsFor: 'reporting' stamp: 'sac 9/26/2001 07:09'!
report: strm 
	"Print a report, with cutoff percentage of each element of the tree  
	(leaves, roots, tree)=2, on the stream, strm."
	self report: strm cutoff: 1! !

!MessageTally methodsFor: 'printing' stamp: 'sac 9/26/2001 07:10'!
fullPrintOn: aStream tallyExact: isExact orThreshold: perCent 
	| threshold |
	isExact
		ifFalse: [threshold _ (perCent asFloat / 1000 * tally) rounded].
	aStream nextPutAll: '**Tree**';
		 cr.
	self
		treePrintOn: aStream
		tabs: OrderedCollection new
		thisTab: ''
		total: tally
		totalTime: time
		tallyExact: isExact
		orThreshold: threshold.
	aStream nextPut: Character newPage;
		 cr.
	aStream nextPutAll: '**Leaves**';
		 cr.
	self
		leavesPrintOn: aStream
		tallyExact: isExact
		orThreshold: threshold! !


!MessageTally class methodsFor: 'spying' stamp: 'sac 9/26/2001 06:51'!
spyOn: aBlock 
	"MessageTally spyOn: [100 timesRepeat: [3.14159 printString]]"
	| node result |
	node _ self new.
	result _ node spyEvery: 1 on: aBlock.
	(StringHolder new
		contents: (String
				streamContents: [:s | node report: s;
						 close]))
		openLabel: 'Spy Results'.
	^ result! !

!MessageTally class methodsFor: 'spying' stamp: 'sac 9/26/2001 06:51'!
spyOn: aBlock toFileNamed: fileName 
	"Spy on the evaluation of aBlock. Write the data collected on a file 
	named fileName."
	| file value node |
	node _ self new.
	value _ node spyEvery: 1 on: aBlock.
	file _ FileStream newFileNamed: fileName.
	node report: file;
		 close.
	file close.
	^ value! !

!MessageTally class methodsFor: 'spying' stamp: 'sac 9/26/2001 06:51'!
spyOnProcess: aProcess forMilliseconds: msecDuration 
	"| p |  
	p _ [100000 timesRepeat: [3.14159 printString]] fork.  
	(Delay forMilliseconds: 100) wait.  
	MessageTally spyOnProcess: p forMilliseconds: 1000"
	| node |
	node _ self new.
	node
		spyEvery: 1
		onProcess: aProcess
		forMilliseconds: msecDuration.
	(StringHolder new
		contents: (String
				streamContents: [:s | node report: s;
						 close]))
		openLabel: 'Spy Results'! !

!MessageTally class methodsFor: 'spying' stamp: 'sac 9/26/2001 06:51'!
spyOnProcess: aProcess forMilliseconds: msecDuration toFileNamed: fileName 
	"Spy on the evaluation of aProcess. Write the data collected on a file  
	named fileName. Will overwrite fileName"
	| file node |
	node _ self new.
	node
		spyEvery: 1
		onProcess: aProcess
		forMilliseconds: msecDuration.
	file _ FileStream fileNamed: fileName.
	node report: file;
		 close.
	file close! !


!SystemDictionary methodsFor: 'snapshot and quit' stamp: 'sac 10/2/2001 11:42'!
setGCParameters
	"Adjust the VM's default GC parameters to avoid premature tenuring."
	"200,000 and 10,000 are more reasonable numbers."
	Smalltalk vmParameterAt: 5 put: 800000.
	"do an incremental GC after this many allocations"
	Smalltalk vmParameterAt: 6 put: 8000! !


!TimeProfileBrowser methodsFor: 'private' stamp: 'sac 9/26/2001 06:51'!
runBlock
	| stream list result |
	tally _ MessageTally new.
	result _ tally spyEvery: 1 on: block.
	stream _ ReadWriteStream
				with: (String
						streamContents: [:s | tally report: s;
								 close]).
	stream reset.
	list _ OrderedCollection new.
	[stream atEnd]
		whileFalse: [list add: stream nextLine].
	self initializeMessageList: list.
	self changed: #messageList.
	self changed: #messageListIndex.
	^ result! !