LeichtgewichtLeichtgewicht

2010/07/11 – 14:33

Architecting as3commons-logging

I recently wrote and deployed the new logging framework for as3commons, here is its story:

Quite a while ago Christophe Herreman and the team of Spring Actionscript thought that their work is useful for more than just Spring and started to publish some of their work at as3commons.

Sidenote: its now released at the as3commons logging homepage.

When trying to use their logging framework I realized that it was quite in its early stage, so I decided to help out by trying to apply all the experience of former projects to make a logging framework supreme. Easier said than done?

Proxy or not?

When requesting getLogger() the framework could have used two ways when returning data:

  1. Create a new proxy per unique getLogger statement.
  2. Create the appropriate setup and return it if available.

The second way was tempting to try because it has one advantage: it occupies less memory. The need to have a logger for every class (and some flash developers might get the strange idea to use one per instance) could potentially mean a lot of loggers.

So I implemented it in a way that I defined the logic in following way: The setup has to be done before any getLogger() call might have been done. It worked well… for me it worked perfectly I knew I had setup my logger before any logging takes place and everything was fine.

In early testing phases co-developers complained because they didn’t know their setup in advance (had to load some xml file) so it wouldn’t work. Others couldn’t guarantee that the setup took place before the loggers got instantiated because it conflicted with some other architecture.

Anyways: I gave up – even though I thought that this approach should have suited ActionScript 3 developers well it failed at the user – so I came to the conclusion:

Return proxies at getLogger().

The function-only approach

A similar attempt to actually provide some easier API failed on a different level. I thought:

“why do we need to have a logger instance at all?

debug(); could make this so much simpler to work with. So I tried it out… and it worked somehow using the Error trick:

   public function debug( ...statement ): void {
      var e: Error = new Error();
      var name: String =  parseErrorStackForName(e.getStackTrace());
      var logger: ILogger = getLoggerForName(name);
   }

The cool thing about this approach is that with high flexibility it would even give the function name which would allow even deeper logging. If arguments.caller from ActionScript 2 would have still been available it might have been maybe reasonably fast. But it wasn’t available and creating Error instances as well as the parsing took just too long to justify this in any way. So my conclusion, as much as it hurt, was:

Stick with the logger proxy!

The Log distribution problem

Okay enough set-backs. Lets go with the stuff that actually makes a difference: The distribution of log output to log methods in the former as3commons implementation and in the flex logging mechanism disappoints. Both for different reasons:

The Flex Logger Event Distribution

I can not tell why the developers at adobe implemented their logging like they did. It doesn’t make a lot of sense to me: They are sending out events at every log statement! See line 131 of LogLogger. This will create a new Event instance with every statement. Beside the fact that it comes with some major problems with the implementation: That is a enormous amount of memory and performance to waste! But they also did something good (better than as3commons): By having the one event sent out for all Loggers the implementation for the various targets it allows to implement just one method and its done.

The former as3commons distribution method

The approach didn’t sound bad: We have a interface that is implemented by a Proxy which itself references to a actual interface. Classic Proxy pattern. This classic pattern, while nice in theory shows some problems in practice:

  • It is not easy to write a target. Any common target does nothing but channeling – taking a log statement and handing it over to some other mechanism to actually draw it. You have to implement 10 methods to simply trace to the trace console. That is way too much.
  • Every method has to call the implementation, even things like “isErrorEnabled”. That will cost a unnecessary amount of time (delegation costs time).
  • For every proxy you need one logger instance. If you don’t have a logger for every proxy there is no way to know output the actual name of the logger. What a waste of memory! Even if you just have a target that directs just every content to trace.

Okay: I planned to make it superior. Here are my rules:

  • The targets need to implement just one method.
  • The proxy and the target don’t share the same interface so I can pass the name and save instances.

Here is what my proxy looked like in my first iteration.

class Logger {
    private var _debugTarget: ILogTarge
    ...
    // not defined in interface, so just internally accessible
    public function setLogTarget( target: ILogTarget, level: int ) {
       _fatalTarget = _errorTarget = ... = null;
       if( level > 0 ) {
          _fatalTarget = target;
         if( level > 1) {
            _errorTarget = target;
            ....
         }
       }
    }
    ...
    public function debug(message:*,...parameters): void {
       if( _debugTarget ) {
          _debugTarget.log( _name, 1 /* Level */, message, parameters );
       }
    }
}

That started to look a lot closer to what I imagined. A target to implement just one method to kill it all and the setup may define where it goes. Great!

In strive of the purpose of a setup

The former as3commons implementation used the same approach as it did with logger. Proxy-Interface pattern. So it creates tons of logger instances, not my approach so I called it differently:

interface ILogSetup {
    function getLogInfo(name:String):ILogInfo;
    // ILogInfo contained the log targets for the levels
}

Well that resulted in one thing: Another bunch of instances that needed to be created for this abstraction layer and a new interface that is essentially a copy of what is available in Logger. So: I dropped the interface and allowed the setups to directly manipulate the proxies:

interface ILogSetup {
    function applyTo(logger:Logger):void;
}

this resulted in change that I had to make the properties available. And I chose to do the unspeakable: I made the properties public.

class Logger {
   public var _errorTarget: ILogTarget;
}

Since there is no way to fill a Logger with wrong content it doesn’t really make a difference in terms of API stability or overall quality, its fast and consumes less of precious space in the output .swf. All good.

All or Some

There a two ways to define how the ILogSetup should fill proxies.

  1. Assume that all loggers are reset and fill just the targets necessary.
  2. Fill all loggers so they don’t need to be reset.

Hint: The second approach is faster, no need to reset all loggers before. But (again) it shows some inconvenience when creating a setup: It is not possible to stack them in any way: The last setup would always overwrite the formerĀ one. So: For the sake of a more flexible setup I went on with the first definition:

Setups should just need to fill whats necessary!

Storing the statements time

Most logging systems just render the time of when the target is called. There is some essential problem with that: What if you don’t have a logger the moment the statement was rendered? (see above: there are cases like that). You’d need some buffer for previous statements and it needs to store time. Now this is the latest statement:

function log( name:String, shortName:String,
              level:LogLevel, timeStamp:Number,
              message:*, parameters:Array ):void;

The final power

Making a class final makes it fast … very fast. With loggers: the debugEnabled and debug statements are called so often. So very, very often. They need to be fast. They were not that fast in the former as3commons framework and they are astonishingly slow in the flex framework. I came myself up with some rule: If a class is easier to be reimplemented than to be extended it became final. Since I reduced the amount of things to do to actually implement a target or a setup, quite many targets could become final and they did.

Constants and Functions

Some thing I learned when writing utils for another project was: If you stuff them into classes they create unnecessary dependencies. Say you want to just trim a string then your .swf shouldn’t contain the code for email verification or whatever else happens to be in the same class. I really do like the function files in AS3 (defining a function in a package). These allow to use just trim, not the rest. Same by the way goes for Singleton. These incredible stupid structures are quite useful for providing a framework out of the box, putting those Singletons into public constants like:

package org.as3commons.logging {
    public const LOGGER_FACTORY: LoggerFactory = new LoggerFactory( ... );
}

Not just it is a lot less to write: If someone needs a LoggerFactory the mechanism to provide that instance is not rendered in the .swf. But beyond that: This constant in its own file is a lot faster than accessing it within a class. So: double win!

Okay so here we are: Of course there have been a lot of details not mentioned here. Find them yourself by using as3commons logging.

Tags: ,

Comments

  1. Tim KeirNo Gravatar

    Hey Martin,

    Nice work!
    I’ve implemented a new Target for the new Monster Debugger 3. It’s based off your original MonsterDebuggerTarget with additional V3 specific params such as Person, Label, etc. I’ve also added in the ability to set default params to specific classes.

    You can view it here:

    https://github.com/ReDrUm/as3-commons-logging/tree/master/com/timkeir/logging

    Feel free to edit it or include it in the core as3-commons-logging.

    Cheers,

    Tim

  2. Martin HeideggerNo Gravatar

    Hello Tim,

    I took a deep look into your implementation and unfortunately couldn’t find a lot to be happy about, but that was mostly due to restrictions of API. Anyways, maybe the most important concept misunderstanding is:

    To provide a logger where the one writing a statement can not be platform specific was one of my major aims.

    In your implementation the developers have been able to develop specifically for MonsterDebugger. And that is something which I think is not reasonable in case one writes a library or alike.

    Also, I tried to implement my log targets in the fastest possible way, putting all that is necessary for configuration out of the log-execution code. In your code configuration can be passed to a log statement that would undermine my initial thoughts.

    In my current implementation (that you can find in the SVN) I seperated the “log” based logging from the “trace” based one and implemented person based loggers globally.

    Do you think you could live with that?

    yours
    Martin.

  3. ArnoudNo Gravatar

    Hi Martin,

    Just a thumbs up here :-)
    thnx for the awesome logging solution. I’m just replacing as3commons-logging 1.0 with 2.5.1 such an improvement!

  4. Martin HeideggerNo Gravatar

    Thanks for the compliment, you are welcome! If you need something make sure to post it in the issue tracker!

Leave a Reply

Site informations

Martin Heidegger – Web Developerskype:mastakanedaxing:martin.heideggertwitter:leichtgewicht