The Trunk: System-ul.253.mcz

Levente Uzonyi uploaded a new version of System to project The Trunk:
http://source.squeak.org/trunk/System-ul.253.mcz

==================== Summary ====================

Name: System-ul.253
Author: ul
Time: 14 February 2010, 9:12:11.268 am
UUID: 7aaed65b-d0e3-0040-8929-0eb0bf8ecf64
Ancestors: System-ar.252

- fix (again): Timer may be already nil in the #ensure: block in MessageTally >> #spyEvery:on: and MessageTally >> #spyAllEvery:on:

=============== Diff against System-ar.252 ===============

Item was changed:
  ----- Method: MessageTally>>spyAllEvery:on: (in category 'initialize-release') -----
  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 isMemberOf: BlockClosure)
  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 := SmalltalkImage current getVMParameters.
  Timer ifNotNil: [ Timer terminate ].
  Timer := [
  [true] whileTrue: [
  | observedProcess startTime |
  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: [
  "Collect gc statistics"
  SmalltalkImage current getVMParameters keysAndValuesDo: [ :idx :gcVal |
  gcStats at: idx put: (gcVal - (gcStats at: idx))].
  "cancel the probe and return the value"
+ Timer ifNotNil: [
+ Timer terminate.
+ Timer := nil ].
- Timer terminate.
- Timer := nil.
  time := Time millisecondClockValue - time0]!

Item was changed:
  ----- Method: MessageTally>>spyEvery:on: (in category 'initialize-release') -----
  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 isMemberOf: BlockClosure)
  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 := SmalltalkImage current getVMParameters.
  Timer ifNotNil: [ Timer terminate ].
  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: [
  "Collect gc statistics"
  SmalltalkImage current getVMParameters keysAndValuesDo: [ :idx :gcVal |
  gcStats at: idx put: (gcVal - (gcStats at: idx))].
  "cancel the probe and return the value"
+ Timer ifNotNil: [
+ Timer terminate.
+ Timer := nil ].
- Timer terminate.
- Timer := nil.
  time := Time millisecondClockValue - time0]!

[hidden email] wrote:
Hi Levente,

How could that happen? Can you post a script to reproduce it?

Thanks,
Juan Vuletich

On Tue, 16 Feb 2010, Juan Vuletich wrote:

Well, the old way to reproduce this is fixed (press alt/cmd+. while
profiling) and that's great. But there's another one, it happens when
you're tallying something which tallies something else. I know this
shouldn't happen normally, but we have some tests which use MessageTally
(for no reason). If you press the "Run Profiled" button in TestRunner,
these tests will set Timer's value to nil and at the end, you get a
debugger.


Levente

>
> Thanks,
> Juan Vuletich
>
>

Levente Uzonyi wrote:
Thanks, I see. Anyway, nested tallies are not working at all (and never
worked). Your fix might give the impression that nested tallies are ok,
when they are not. Perhaps it would be best to just raise an error.

Cheers,
Juan Vuletich

On Tue, 16 Feb 2010, Juan Vuletich wrote:

I agree that it's not the best solution and it shadows an issue. We could
just fix the tests and revert the code. But I think that changing the
value of a class variable from instance methods is a sign of bad design.
Why is MessageTally using the class variable Timer instead of an instance
variable?


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?

>
> Cheers,
> Juan Vuletich
>
>

Levente Uzonyi wrote:
Indeed.

> 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 :).

> 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.

Cheers,
Juan Vuletich

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.

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 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.


Levente

> Cheers,
> Juan Vuletich
>

Levente Uzonyi wrote:
yes.

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

Juan Vuletich wrote: 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

'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!

On Fri, 19 Feb 2010, Juan Vuletich wrote:

Thanks, this looks good. The only thing I don't understand is that why
CodeHolder is better than StringHolder to view the report of MessageTally?
I found no use of the buttons. Is there anything different about
CodeHolder and StringHolder in Cuis?


Levente

> Cheers,
> Juan Vuletich
>

Levente Uzonyi wrote:
In Cuis, a StringHolder uses a TextEditor and a CodeHolder uses a
SmalltalkEditor. So, a CodeHolder adds handy Smalltalk shortcuts like
alt-m. BTW, if you take a close look at Cuis, I'm sure you'd be porting
tons of stuff back to Squeak.

Cheers,
Juan Vuletich
>
>
> Levente
>
>> Cheers,
>> Juan Vuletich

On Sun, 21 Feb 2010, Juan Vuletich wrote:

Thanks for the explanation.

> BTW, if you take a close look at Cuis, I'm sure you'd be porting tons of
> stuff back to Squeak.

That's probably true and I guess other people would do the same. A few
pointers would be helpful.


Levente

Levente Uzonyi wrote:
>> BTW, if you take a close look at Cuis, I'm sure you'd be porting tons
>> of stuff back to Squeak.
>
> That's probably true and I guess other people would do the same. A few
> pointers would be helpful.
>
>
> Levente

Ok. Some things that could be worth bringing into Squeak are:
- #is: as a replacement for #isXXX. See implementors and senders of #is:
in Cuis.   I believe this is a big improvement.
- closure analysis in method annotations
- 0077-ProtocolCatcher-jmv.1.cs
- 0099-ChronologyEnh-jmv.1.cs
- New exceptions for more flexible handling of Socket and FileWrite failures
- This last one is a bit larger. I did a serious redesign of TextStyles
and TextAttributes, also affecting NewParagraph and the CharacterScanner
hierarchy. This makes it easier to write editors that have a concept of
style that is closer common text editors. It also adds new functionality
to the TextStyles. Paragraph removal.

Another one that is great although a bit risky is to make #fork and
friends answer nil instead of the created process. See comment at #fork.

Many Cuis features are already in Squeak, like AA StrikeFonts, new
Editor hierarchy, MessageTally enh. And there are many other things that
could be useful. You can check a bit the list of change sets for Cuis,
and see if something calls your attention.

Cheers,
Juan Vuletich