I was asked to do a quick review of Zend_Log the other day to see what I thought of it. Was it good enough to use instead of trying to roll your own or relying on the outdated Log package in PEAR? I should qualify "outdated". By that I mean it uses PEAR_Error and jumps through hoops to work in PHP4. That's a pretty limiting definition of outdated, I know, but that's the one I'm working from right now.
Back on topic. The short answer to is Zend_Log good (enough): yes; the long answer, no. First off, it does what it needs to do without too much fuss. It's documentation is excellent, it has no outside dependencies, and plenty of flex points. All in all a well put together package.
But... It has a few fatal flaws in my opinion. First off, there is redundancy within the code. The one I noticed the most was filtering. When you call the log() method, it runs through all of its filters. A filter can effectively veto a log entry. Nice functionality to have, but only if you're using it. To me that functionality seems like something that should happen at the writer level, however. Open up the base writer object, and sure enough it does. So you have two levels of filtering, something that's probably not going to be used by many users.
I would have created a Zend_Log_Writer_Filterable object that would add filtering in if you needed it. To filter, you instantiate a Filterable type and one of the options passed into it would be the end writer you want to use, stream, db, etc. This gives you the functionality that could be very useful in certain cases, but keeps it from causing performance hits against the main class.
Second up, the way writers themselves are handled. If I'm looking for speed, I want to talk directly to the object that's going to be writing the data. In the case of Zend_Log, the writers aren't accessible directly, and if they were instantiated directly their API is different from Zend_Log.
I put together a simple, some might say simplistic, test (source) to see what kind of effect a straight double-callback would cause. To make it complete, I compared it with iterating over an array with just one value to see what kind of hit the code would take for the array being in place.
The results were as I expected, though a little more dramatic than I thought they would be. The double-call - calling a method that only calls another - causes a hit of more than 100% when compared to calling that method directly. If you take that, and add a foreach() over an array with one value, it takes a hit of another 50%. To me, that means that Zend_Log::log() is 200% slower than it could be if I could access the writer directly.
The flexibility is good, but this code puts it above performance. Having multiple loggers and filters in the base class is kitchen sink syndrome. In the cases where it's needed, special writers could have stepped in to fill the void.
In conclusion, I think the Zend_Log code does too much. In my opinion, it should serve as a Factory for creating new loggers, and I would give it the ability to work as a container for any writer if it was instantiated directly.
Is the code good enough? Yeah, if you're in a pinch or don't really care about milliseconds. If you're looking for a class with a very narrow - possibly even limiting - scope that's as fast as it can be, this one isn't it.
Update: I just ran the same test code above on a server with Zend Platform installed. The single and double callbacks are basically the same (faster, but still a similar difference). The multi-callbacks however ran much slower in comparison. The double was 215% slower than the straight single, and the multi was 242% slower than the double. That means that running an opcode cache with an array when a single value could have been used causes a huge performance hit. Granted, huge is getting into thousandths of a second, but they all add up.
4 comments
First off, the only penalty you're paying performance-wise if you don't use the writer-level filter functionality is a one extra method call to write() vs. _write() (and there might be other functionality stuck in here for the future, so the filter functionality isn't necessarily the culprit here) and iterating across an empty array. So, let's just assume it doubles the time of a log event that passed the global filters, but fails a writer filter. But then, you've said yourself that people don't use writer-level filters much so this probably isn't a very common case, which is also my experience. That means that by this point, we're very likely to log this event and the time it takes to write the log event will far outweigh the performance cost here. This points to a very significant flaw in your performance test- you don't actually *log* anything! Of course, the time it takes to actually log an event far outweighs any of this piddling method calling or array iteration. So you're testing an very uncommon scenario with the assumption that no events are ever really logged. I'm not going to lose sleep at night if Zend_Log isn't optimized for this. ;)
Secondly, if it's direct access to the writers you want, why use Zend_Log at all? You shouldn't, because obviously your app doesn't require anything near this complex and you don't think it will in the foreseeable future. I don't see that as a flaw in Zend_Log.
BTW, I do see some serious problems with Zend_Log now that you've brought my attention to it. The most common case of not logging based on a global priority is not optimized. I do consider that a flaw, and I'll try to schedule a fix for it in the next release.
The larger issue here is the kitchen sink design. ZF claims to utilize design patterns but there are any number of patterns here that were completely ignored in favor of providing as much functionality as possible. I would argue that multiple writers and filters are both edge cases and should have been provided by another means instead of forcing the functionality on all users.
If the functionality comes without a cost, its great to put it in, but if there is a performance penalty, I see no reason to include the functionality when it can be done with additional objects. Filtering should be handled via Decorators and multiple writers should be handled by a Composite/Proxy to delegate the need for dispatching a log message to multiple writers.
Finally, I think it is a poor API design to force user through the Zend_Log. Zend_Log should be considered a convenience object that implements a Zend_Log_Writer interface with each of the back-ends implementing the same interface. This promotes polymorphism by declaring a specific interface that can be depended on via type hinting and makes the package useable in situations where as much speed as is possible is necessary by eliminating the necessity of a double-callback.
I feel this is a larger issue with ZF in general. Granted, I have not done a thorough review of all of the components, but the parts that I have gone through (mostly Core components) all share the kitchen sink philosophy. These "features" come at a very high cost. Not that in the milliseconds that are wasted on each call, but in that you can't optimize the code until ZF 2.0 without breaking existing code.
I think I did a disservice by focusing so much on the #s and less on the underlying issues that they represent. I hope that helps clarify my point.
Travis' topic wasn't so much "here's why _Log is slow". It's more a case study in design choices visible in certain parts the code. His point seems to me to be "this part of the code could be improved by a redesign to foo and bar", whereas on the surface your rebuttal seems to be "that's not the slowest part of the code anyway, so there!"
Had Travis' key point been "my ideas will make it faster overall", as if this was a performance profiling session's result, then I'd be inclined to agree with you, "why focus on that when write() operations are inherently slower". But that was not his point...
Also when you compare glue frameworks to stack frameworks, the glue sniffers are already much lighter than their stacked brethren. That in itself is probably as far as you're going to get in the optimization realm, no?
Otherwise the framework has too many moving parts in order for Joe Coder to get down and get done.
Or maybe I just need to eat more fiber, I'm a bit frameworked out.
Comment feed for this post