+972 52-548-6969
NHProfLogging interception
One of the goals that I set for myself with the NHibernate Profiler is to be able to run on unmodified NHibernate 2.0. The way that I do that is by intercepting and parsing the log stream from NHibernate.
NHibernate logging is extremely rich and detailed, so anything I wanted to do so far was possible. I am pretty sure that there would come a time when a feature would require more invasive approaches, running profiler code in the client application to gather more information, but for now this is enough.
I did run into several problems with logging interception. Ideally, I want this to happen on the fly, as we go. So I really want to get the real time logging stream. The problem is how to do so. I started with the UdpAppender, but that doesn't work on Vista in the released version. Remoting Appender is what I am using now, but it has one critical issue, it is an async appender, so message can (and do) appear out of order.
The message order is pretty important to the profiler. It can deal with that, but it would lead to surprising results. So that one is out as well.
The only other appender that comes out of the box with log4net and can be used remotedly is the telnet appender, which is next on the list for exploring. It does mean that the profiler has to connect to the application, rather than the other way around, which can be a problem.
I built an appender that fit my needs, and I am using it now to test how the profiler works, but before starting to deal with the telnet appender, I thought it would be a good time to ask.
How important is "running on unmodified NHibernate" is?
I am not talking about having a profiler build of NHibernate, I am talking about doing things like using the profiler appender, or registering an HttpModule.
More posts in "NHProf" series:
- (02 Dec 2008) What is the role of the DBA?
- (01 Dec 2008) The stack is not as simple as you wish it to be
- (21 Oct 2008) Logging interception
- (13 Oct 2008) Another milestone
- (13 Oct 2008) Alive! It is alive!
Comments
I was going to ask if it were possible to build your own appender that does what you want. But it looks like you're already going down that path.
I think that as long as I don't have to actually modify the source code, but just add an appender or something configurable like that, it should be just fine. I'm already doing stuff like selectively enabling an appender when I want to see certain things in the log.
Looks like you've finally realized the log4net weakness and hopefully maybe now you can see there is, in fact, a difference between log4net and NLog.
Another reason why I vote for NLog as default logging system for NHibernate.
http://www.nlog-project.org/targets.html
log4net stinks with its weak configurability.
With NLog, all targets are sync unless otherwise specified. Whether or not a target is Sync or Async, should be no concern of the target, but of a matter of configuration and choice.
The choice of logging libraries is sort of a religious argument for me.. sorry :P. But I’m sure we can agree on common ground here:
http://netcommon.sourceforge.net/index.html
which is a portable logging abstraction that allows you to change the underlying logging between a variety of logging libraries log4net / NLog / EntLib Log (while maintaining each of their configurability advantages). I think NHibernate needs to move toward netcommon logging to resolve issues like this. It would only be a matter of changing an App.config to switch your logging implementation. I’ll even submit a patch with Common.Logging feature if you think it’d be accepted.
Been meaning to adapt one of the logging libraries to work with the facilities provided by the System.Net.PeerToPeer namespace. Thanks for reminding me...
Not sure if this helps, but I found a reference to a thread where someone had the same issue with UdpAppender/Vista and proposed a simple fix:
www.codeplex.com/.../View.aspx?ThreadId=23992
I have no idea if this fixes the problem or not but figured I'd offer the link since I recall reading about it.
Brian,
Um, there is nothing in log4net that is weak.
I am talking specifically about the default appenders. The UDP one would have been perfect, probably, but a bug exists that make it fail on Vista machines (well, IPV6 machines) in the version that comes with NH.
log4net is extremely configurable, so I am not sure what you are getting at. The specific appender that I am talking about is not supporting the option that I would like. I can write a new appender that does just what I want, plug it in, and I am done.
In fact, that is what I did.
Regarding common logging, please raise the subject in the mailing list, although I must say that I don't really see a way to make this work. NH makes assumptions about the way logging works, which match the way log4net behaves.
As long as it's only a configuration change I personally wouldn't mind it. Maybe I could even tell the profiler where my config is and it could make the change for me?
Shane,
That might also mean having to copy a profiler provided dll to the bin directory.
And yes, automatically editing the config is a feature that I plan to have.
I personally don't mind the dll requirement. Every time I build the rhino mocks dll is copied into my bin but that doesn't stop me from using it.
What do you mean by "real time logging stream"? Do you want to capture NHibernate related messages as soon as possible before they go through log4net so you can capture better timing information?
I have a feeling these won't fix the ordering problem, but they are fun to bring up anyway..
Google the following:
Lamport Timestamps
Vector Clocks
You're a sharp guy, so if there was an easy way to fix the ordering thing, I'm sure you'd have done it. BUT your post reminded me of these two topics anyway. :-)
Ron,
What I mean by that is that as soon as the message hit log4net, I want to receive it.
If remoting appender was syncronous, it would have been perfect.
Evan,
The problem is that my initial goal was to work on NH & log4net unchanged.
If I modify the stream source, then I can easily handle the problem anyway.
What about contributing a patch to the log4net project (or if it's already fixed), packing a new versioni of log4net with NH?
If you can't modifiy the NH release, then just pack your compiler with the new version an require users to update their installation to a new log4net version.
There shouldn't be any breaking changes with a new log4net release I guess.
And you get the benefit of not having to write any code, just stick to the UDP Appender.
I vote for use an unmodified NHiberate, because otherwise the people have to wait until you provide a patch or publish your NHibernate dll if NHibernate releasing a new version.
I also vote for creating a custom appender for log4net in this case. It isnt a problem to distribute your custom log4net appender with my application if i want to use your profiler, because i dont need to change my code, i only need to modify my log4net configuration.
For those how want to use NLog with NHibernate, you can simply create a log4net NLog forwarder appender.
Daniel,
I think that having a custom appender is going to be what I will do.
I don't think you should modify nHibernate as Steve pointed out; however, adding additional components around nHibernate is no problem.
I would not require an httpmodule unless your only planning on supporting asp.net applications, and I would be more hestitant to inject something in the asp.net pipeline.
Comment preview