Juan Vuletich wrote:
> Levente Uzonyi wrote:
>> On Tue, 16 Feb 2010, Juan Vuletich wrote:
>>
>>> Levente Uzonyi wrote:
>>>> Why is MessageTally using the class variable Timer instead of an 
>>>> instance variable?
>>>
>>> I really don't know. Perhaps to make it clear that nested tallies 
>>> are not supported? BTW, I've just looked in Squeak 1.1, and it uses 
>>> the Timer variable the same way. Hey, I even opened Apple 
>>> Smalltalk-80, and it is the same too :).
>>>
>>
>> Thanks for the research, it's good to know the original design 
>> decision. Too bad the class comment doesn't tell anything about it. 
>> We should fix that.
>
> yes.
>
>>
>>>> Levente
>>>>
>>>> P.S.:
>>>> I added a new instance variable timer to MessageTally, replaced all 
>>>> occurence of Timer to timer, removed the #ifNotNil: checks and 
>>>> successfully profiled the tests. Is anything wrong with this approach?
>>>
>>> I just tried the same. It seems to work. But  it seems whoever wrote 
>>> MessageTally knew what he was doing. Using an instance variable 
>>> would have been the obvious choice. But they decided to use a class 
>>> variable. Mhhh. I looked at the old books and found nothing. Looking 
>>> at Squeak 1.1. and Smalltalk-80, I believe it was because at that 
>>> time there was no #ensure: and they wanted to be sure to kill the 
>>> process, as it won't stop if you got a walkback or pressed alt-.. So 
>>> I guess your proposal is ok. But on the other hand, I see no value 
>>> in supporting nested tallies, and your proposal would require some 
>>> testing.
>>>
>>> So, if you're willing to see how it works, and perhaps revert it if 
>>> some problem arises, I'd say go ahead with it.
>>>
>>
>> I agree there's no value in nested tallies, MessageTally doesn't give 
>> meaningful results even if timer is an instance variable in this case.
>> And I think you're right, MessageTally should raise an error if a 
>> timer process is already running, but the error should be raised when 
>> the second process is about to be created, not when the first is 
>> about to be terminated.
>
> I guess that would be best. Although maybe we get some error for some 
> old hung Timer process. If that ever happens, at least, it would call 
> our attention...
>
>>
>> I realized that the timer process is terminated by Debugger >> 
>> #process:controller:context: and not nested tallies when running all 
>> the tests profiled, since no MessageTally is created directly by tests.
>> So replacing Timer with an instance variable is not a good idea, 
>> since the debugger has to stop the timer process somehow, but maybe 
>> suspending/resuming is enough.
>
> Oh! Horrible code! First thing to do is to change MessageTally>>#close 
> to #closeTally, and fix senders. At least, that makes it easy to spot 
> which the real senders are. I really hate "false polymorphism"! After 
> that, creating a new instance only to send #close... Really awful. 
> Changed that to a #terminateTimerProcess class message.
>
> I'd say the only reason to kill the process is (again) that there was 
> no #ensure: back then. It would be best not to do it at all. The Timer 
> process should end or be terminated without such hacks.
>
> If we can handle properly Timer termination, and ensure there is no 
> way to leave it running, we could remove #closeTally and 
> #terminateTimerProcess, and then make Timer an instance variable.
>
> Cheers,
> Juan Vuletich

Ok. It seems the class variable is needed for the debugger. Letting the 
debugger terminate the Timer greately enhances UI responsiveness when 
doing Alt-. during a tally. So I left it there. What is not needed 
anymore AFAIK is the #close method, as #ensure: ensures terminating it 
in the normal (non-debugger) case. The attach also includes raising an 
error in case of nested a tally being started. I did it in Cuis, and 
will be in the next Cuis release. Levente, feel free to test and publish 
for Squeak, or to take ideas from it.

Cheers,
Juan Vuletich
-------------- next part --------------
'From Cuis 2.0 of 12 February 2010 [latest update: #418] on 19 February 2010 at 2:53:03 pm'!

!Debugger methodsFor: 'private' stamp: 'jmv 2/19/2010 13:03'!
process: aProcess controller: aController context: aContext
	super initialize.
	Smalltalk at: #MessageTally ifPresentAndInMemory: [ :c | c terminateTimerProcess ].
	contents _ nil. 
	interruptedProcess _ aProcess.
	contextStackTop _ aContext.
	self newStack: (contextStackTop stackOfSize: 1).
	contextStackIndex _ 1.
	externalInterrupt _ false.
	selectingPC _ true.
	errorWasInUIProcess _ false! !


!MessageTally methodsFor: 'initialize-release' stamp: 'jmv 2/19/2010 14:49'!
spyAllEvery: millisecs on: aBlock
	"Create a spy and spy on the given block at the specified rate."
	"Spy all the system processes"

	| myDelay time0 |
	aBlock isBlock
		ifFalse: [ self error: 'spy needs a block here' ].
	self class: aBlock receiver class method: aBlock method.
		"set up the probe"
	myDelay := Delay forMilliseconds: millisecs.
	time0 := Time millisecondClockValue.
	gcStats _ Smalltalk getVMParameters.
	Timer ifNotNil: [ self error: 'it seems a tally is already running' ].
	Timer _ [
		[true] whileTrue: [
			| startTime observedProcess |
			startTime := Time millisecondClockValue.
			myDelay wait.
			observedProcess := Processor preemptedProcess.
			self
				tally: observedProcess suspendedContext
				in: observedProcess
				"tally can be > 1 if ran a long primitive"
				by: (Time millisecondClockValue - startTime) // millisecs].
		nil] newProcess.
	Timer priority: Processor timingPriority-1.
		"activate the probe and evaluate the block"
	Timer resume.
	^ aBlock ensure: [
		"cancel the probe and return the value"
		"Could have already been terminated. See #terminateTimerProcess"
		Timer ifNotNil: [
			Timer terminate.
			Timer _ nil ].
		"Collect gc statistics"
		Smalltalk getVMParameters keysAndValuesDo: [ :idx :gcVal | 
			gcStats at: idx put: (gcVal - (gcStats at: idx))].
		time := Time millisecondClockValue - time0]! !

!MessageTally methodsFor: 'initialize-release' stamp: 'jmv 2/19/2010 14:50'!
spyEvery: millisecs on: aBlock
	"Create a spy and spy on the given block at the specified rate."
	"Spy only on the active process (in which aBlock is run)"

	| myDelay time0 observedProcess |
	aBlock isBlock
		ifFalse: [ self error: 'spy needs a block here' ].
	self class: aBlock receiver class method: aBlock method.
		"set up the probe"
	observedProcess _ Processor activeProcess.
	myDelay := Delay forMilliseconds: millisecs.
	time0 := Time millisecondClockValue.
	gcStats _ Smalltalk getVMParameters.
	Timer ifNotNil: [ self error: 'it seems a tally is already running' ].
	Timer _ [
		[ true ] whileTrue: [
			| startTime |
			startTime := Time millisecondClockValue.
			myDelay wait.
			self
				tally: Processor preemptedProcess suspendedContext
				in: (observedProcess == Processor preemptedProcess ifTrue: [observedProcess] ifFalse: [nil])
				"tally can be > 1 if ran a long primitive"
				by: (Time millisecondClockValue - startTime) // millisecs].
		nil] newProcess.
	Timer priority: Processor timingPriority-1.
		"activate the probe and evaluate the block"
	Timer resume.
	^ aBlock ensure: [
		"cancel the probe and return the value"
		"Could have already been terminated. See #terminateTimerProcess"
		Timer ifNotNil: [
			Timer terminate.
			Timer _ nil ].
		"Collect gc statistics"
		Smalltalk getVMParameters keysAndValuesDo: [ :idx :gcVal | 
			gcStats at: idx put: (gcVal - (gcStats at: idx))].
		time := Time millisecondClockValue - time0]! !

!MessageTally methodsFor: 'initialize-release' stamp: 'jmv 2/19/2010 14:44'!
spyEvery: millisecs onProcess: aProcess forMilliseconds: msecDuration
	"Create a spy and spy on the given process at the specified rate."
	| myDelay time0 endTime observedProcess sem |
	(aProcess isKindOf: Process)
		ifFalse: [self error: 'spy needs a Process here'].
	self class: aProcess suspendedContext receiver class method: aProcess suspendedContext method.
	"set up the probe"
	observedProcess _ aProcess.
	myDelay _ Delay forMilliseconds: millisecs.
	time0 _ Time millisecondClockValue.
	endTime _ time0 + msecDuration.
	sem _ Semaphore new.
	gcStats _ Smalltalk getVMParameters.
	Timer ifNotNil: [ self error: 'it seems a tally is already running' ].
	Timer _ [
			[
				| startTime |
				startTime _ Time millisecondClockValue.
				myDelay wait.
				self
					tally: Processor preemptedProcess suspendedContext
					in: (observedProcess == Processor preemptedProcess ifTrue: [ observedProcess ] ifFalse: [nil])
					"tally can be > 1 if ran a long primitive"
					by: (Time millisecondClockValue - startTime) // millisecs.
				startTime < endTime
			] whileTrue.
			sem signal.
		] newProcess.
	Timer priority: Processor timingPriority-1.
		"activate the probe and evaluate the block"
	Timer resume.
	"activate the probe and wait for it to finish"
	sem wait.
	"Collect gc statistics"
	Smalltalk getVMParameters keysAndValuesDo: [ :idx :gcVal | 
		gcStats at: idx put: (gcVal - gcStats at: idx)].
	time _ Time millisecondClockValue - time0! !


!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
spyAllOn: aBlock
	"Spy on all the processes in the system
	
	[1000 timesRepeat: [3.14159 printString. Processor yield]] fork.
	[1000 timesRepeat: [20 factorial. Processor yield]] fork.
	[1000 timesRepeat: [20 factorial. Processor yield]] fork.
	MessageTally spyAllOn: [ (Delay forMilliseconds: 100) wait]
	
	"
	| node result |
	node _ self new.
	node reportOtherProcesses: true.	"Irrelevant in this case. All processes will be reported on their own."
	result _ node spyAllEvery: self defaultPollPeriod on: aBlock.
	(CodeHolder new contents: (String streamContents: [:s | node report: s]))
		openLabel: 'Spy Results' wrap: false.
	^ result! !

!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
spyOn: aBlock reportOtherProcesses: aBoolean
	"
	Spy on aBlock, in the current process. Can include or not statistics on other processes in the report.
	[1000 timesRepeat: [
		100 timesRepeat: [120 factorial].
		(Delay forMilliseconds: 10) wait
		]] forkAt: 45 named: '45'.
	MessageTally spyOn: [10000 timesRepeat: [1.23 printString]] reportOtherProcesses: true
	"
	| node result |
	node _ self new.
	node reportOtherProcesses: aBoolean.
	result _ node spyEvery: self defaultPollPeriod on: aBlock.
	(CodeHolder new contents: (String streamContents: [:s | node report: s]))
		openLabel: 'Spy Results' wrap: false.
	^ result! !

!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
spyOn: aBlock toFileNamed: fileName reportOtherProcesses: aBoolean
	"Spy on the evaluation of aBlock. Write the data collected on a file
	named fileName."

	| file value node |
	node _ self new.
	node reportOtherProcesses: aBoolean.
	value _ node spyEvery: self defaultPollPeriod on: aBlock.
	file _ FileStream newFileNamed: fileName.
	node report: file.
	file close.
	^value! !

!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
spyOnProcess: aProcess forMilliseconds: msecDuration reportOtherProcesses: aBoolean
	"
	Spy on aProcess for a certain amount of time
	| p1 p2 |  
	p1 _ [100000 timesRepeat: [3.14159 printString. Processor yield]] newProcess.  
	p2 _ [100000 timesRepeat: [3.14159 printString. Processor yield]] newProcess.
	p1 resume.
	p2 resume.  
	(Delay forMilliseconds: 100) wait.  
	MessageTally spyOnProcess: p1 forMilliseconds: 1000 reportOtherProcesses: true
	"
	| node |
	node _ self new.
	node reportOtherProcesses: aBoolean.
	node
		spyEvery: self defaultPollPeriod
		onProcess: aProcess
		forMilliseconds: msecDuration.
	(CodeHolder new
		contents: (String
				streamContents: [:s | node report: s]))
		openLabel: 'Spy Results' wrap: false! !

!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
spyOnProcess: aProcess forMilliseconds: msecDuration toFileNamed: fileName reportOtherProcesses: aBoolean
	"Spy on the evaluation of aProcess. Write the data collected on a file  
	named fileName. Will overwrite fileName"
	| file node |
	node _ self new.
	node reportOtherProcesses: aBoolean.
	node
		spyEvery: self defaultPollPeriod
		onProcess: aProcess
		forMilliseconds: msecDuration.
	file _ FileStream fileNamed: fileName.
	node report: file.
	file close! !

!MessageTally class methodsFor: 'spying' stamp: 'jmv 2/19/2010 14:41'!
tallySendsTo: receiver inBlock: aBlock showTree: treeOption
	"
	MessageTally tallySends: [3.14159 printString]
	"
	"This method uses the simulator to count the number of calls on each method
	invoked in evaluating aBlock. If receiver is not nil, then only sends
	to that receiver are tallied.
	Results are presented as leaves, sorted by frequency,
	preceded, optionally, by the whole tree."
	| prev tallies startTime totalTime |
	startTime _ Time millisecondClockValue.
	tallies _ MessageTally new class: aBlock receiver class method: aBlock method.
	tallies reportOtherProcesses: true.	"Do NOT filter nodes with nil process"
	prev _ aBlock.
	thisContext sender
		runSimulated: aBlock
		contextAtEachStep: [ :current |
			current == prev ifFalse: [ "call or return"
				prev sender == nil ifFalse: [ "call only"
					(receiver == nil or: [ current receiver == receiver ])
						ifTrue: [ tallies tally: current by: 1 ]].
				prev _ current]].

	totalTime _ Time millisecondClockValue - startTime // 1000.0 roundTo: 0.01.
	(CodeHolder new contents:
		(String streamContents: [ :s |
			s nextPutAll: 'This simulation took ' , totalTime printString, ' seconds.'; cr.
			treeOption
				ifTrue: [ tallies fullPrintExactOn: s ]
				ifFalse: [ tallies leavesPrintExactOn: s ]]))
		openLabel: 'Spy Results' wrap: false! !

!MessageTally class methodsFor: 'private' stamp: 'jmv 2/19/2010 14:43'!
terminateTimerProcess

	Timer ifNotNil: [ Timer terminate ].
	Timer _ nil! !


!TimeProfileBrowser methodsFor: 'private' stamp: 'jmv 2/19/2010 14:42'!
runBlock: aBlock pollingEvery: pollPeriod 
	| stream list result |
	block := MessageSend 
				receiver: self
				selector: #runBlock:pollingEvery:
				arguments: { 
						aBlock.
						pollPeriod}.	"so we can re-run it"
	tally := MessageTally new.
	tally
		reportOtherProcesses: false;
		maxClassNameSize: 1000;
		maxClassPlusSelectorSize: 1000;
		maxTabs: 100.
	result := tally spyEvery: pollPeriod on: aBlock.
	stream := ReadWriteStream 
				with: (String streamContents: [ :s | 
					tally report: s]).
	stream reset.
	list := OrderedCollection new.
	[stream atEnd] whileFalse: [list add: stream nextLine].
	self initializeMessageList: list.
	self changed: #messageList.
	self changed: #messageListIndex.
	^result! !

!TimeProfileBrowser methodsFor: 'private' stamp: 'jmv 2/19/2010 14:42'!
runProcess: aProcess forMilliseconds: msecDuration pollingEvery: pollPeriod 
	| stream list result |
	block := MessageSend 
				receiver: self
				selector: #runProcess:forMilliseconds:pollingEvery: 
				arguments: { 
						aProcess.
						msecDuration.
						pollPeriod}.	"so we can re-run it"
	tally := MessageTally new.
	tally
		reportOtherProcesses: false;
		maxClassNameSize: 1000;
		maxClassPlusSelectorSize: 1000;
		maxTabs: 100.
	result := tally 
				spyEvery: pollPeriod
				onProcess: aProcess
				forMilliseconds: msecDuration.
	stream := ReadWriteStream 
				with: (String streamContents: [ :s | 
							tally report: s]).
	stream reset.
	list := OrderedCollection new.
	[stream atEnd] whileFalse: [list add: stream nextLine].
	self initializeMessageList: list.
	self changed: #messageList.
	self changed: #messageListIndex.
	^result! !

MessageTally removeSelector: #close!
MessageTally removeSelector: #closeTally!