Logging, Notifications and DynamicVariables (was: Re: [squeak-dev] The Trunk: Collections-cmm.538.mcz)

Levente Uzonyi leves at elte.hu
Thu Oct 3 02:07:43 UTC 2013


On Wed, 2 Oct 2013, Chris Muller wrote:

> On Tue, Oct 1, 2013 at 10:22 PM, Levente Uzonyi <leves at elte.hu> wrote:
>> On Tue, 1 Oct 2013, Chris Muller wrote:
>>
>>> In the context of Smalltalk-80, I can understand logging straight to
>>> Transcript and using Transcript-specific functions (e.g., endEntry).
>>> Today, I consider referencing Transcript directly to be bad-form,
>>> simply because it tightly binds code to a particular UI.
>>>
>>> I prefer to signal Notifications to let the what-is-logged remain
>>> independent of the where-its-logged.
>>
>>
>> Notifications kill performance. Here's a small comparison of using no
>> logging at all, using Notifications for logging, and using a
>> ProcessLocalVariable for logging:
>
> This is very interesting, thanks a lot for the code examples.  I did
> not know about ProcessSpecificVariable; it reminds me of the
> DynamicBindings external package.  Although these code examples appear
> to not be using DynamicVariable quite correctly (i.e., DynamicVariable
> class>>#value:during: does not accept an argument to its block); I
> understand the concept you're presenting -- that a Dictionary lookup
> is faster than a stack-walking Notification.

Just try running them in a workspace. They will work. I've passed two 
blocks to #value:during:, which might be misleading at first sight. The 
first argument could be any object, but I used a block as a callback. 
The second argument of the method should be a block with zero arguments, 
and it has just as many.
I used the classes Notification and DynamicVariable in order to keep these 
examples simple, but in practice one should create subclasses of them.

Here's the same example using a subclass with a few methods:

| counter logger|
counter := 0.
logger := Logger new.
logger logDuring: [
 	100000 timesRepeat: [
 		[
 			counter := counter + 1.
 			Logger log: counter ] value ] ]

DynamicVariable subclass: #Logger
 	instanceVariableNames: ''
 	classVariableNames: ''
 	poolDictionaries: ''
 	category: 'LoggerExample'

Logger class >> log: anObject

 	self value ifNotNil: [ :logger | logger log: anObject ]

Logger >> logDuring: aBlock

 	self class value: self during: aBlock

Logger >> log: anObject

 	"logging happens here"

>
> It's always good to remember the costs of using Notifications.  I do
> think to generically say, "they kill performance" is a little
> misleading, though, since no one is going to log inside of a
> tight-loop.  If they did, they're gonna have bloated logs and
> performance issues anyway.  I think logging should be used sparingly,
> focusing on high-value messages; such as once at the start of
> long-running process, or the details of an exceptional circumstance.
> Used that way, performance is not affected.

It depends on how logging is implemented, but you're right about that the 
overall cost can be made insignificant.

>
> Performance being equal leaves us to consider the aesthetic quality of
> each approach.  I want logging code to have as little (visual) impact
> on reading a method as possible.  Here I think Notifications are
> better because they avoid the ifNotNil: conditional construct.
>
> Additionally, with the built-in hierarchical structure of
> Notifications, package-local logging is easily accomplished.
> Attempting this with ProcessLocalVariable approach might require more
> "lattice" in the signaling code, such as:
>
>    MagmaLinkChange signal: 'Link changed'
>
> vs.
>
>    ProcessLocalVariable ifNotNil: [ : logger | logger log: 'Link
> changed' atLevel: MagmaLinkChange ]

See my example above.

>
> And, actually, this example (MagmaLinkChange) not only logs but
> carries additional state on which the system must act.  Having a
> single global handle all logging would not be able to handle some of
> these one-off cases.
>
> Like everywhere in engineering, I guess the optimal balance of
> trade-offs must be assessed for every situation.

My point is that you can do the same with process local variables as with 
exceptions, if you don't want to access the stack itself.

>
> --- snipped the code examples ---
>
>>>> always "Transcript" or "self". Replacing #endEntry with #flush won't hurt
>>>> in
>>>> most cases.
>>>
>>>
>>> "Most" cases, or all?  I was intending to change all of MY sends of
>>> endEntry to flush (if any), is there a caveat?
>>>
>>
>> Yes. Replacing #endEntry with #flush in Transcript >> #flush would lead to
>> infinite recursion. In some methods the receiver of #endEntry is a
>> Transcripter, which doesn't have its own implementation of #flush. Without
>> that it would break.
>
> Ha, ok!  Funny man!   :)
>

:)


Levente


More information about the Squeak-dev mailing list