A friend of mine pointed me in the direction of a cool library for Aspect Oriented Programming called PostSharp the other day. I’d read about AOP in the past, but always had so much going on that it slipped my mind to look further into it. But, his excitement rubbed off on me and it wasn’t long before I thought of a way I could use it. I’d been wanting to set up logging on a site I’ve been working on so that I could collect data for a while and report on it to see which controller methods are running the slowest. Not a permanent solution, just a way to gather data for a while to analyze it and identify any pain points I may have missed. Using PostSharp I can do it without littering too much logging code throughout the controllers themselves (all they would need is an attribute).
First thing we need to do is create a table to log to. Something like this:
MySQL | |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 | CREATE TABLE `my_site`.`log` ( `ID` int(10) unsigned NOT NULL auto_increment, `Date` datetime NOT NULL, `Thread` varchar(32) NOT NULL, `Context` varchar(10) NOT NULL, `Level` varchar(10) NOT NULL, `Logger` varchar(512) NOT NULL, `Method` varchar(200) default NULL, `Parameters` varchar(8000) default NULL, `Message` varchar(1000) NOT NULL, `Exception` varchar(4000) default NULL, `ExecutionTime` decimal(14,4) default NULL, PRIMARY KEY (`ID`), INDEX `ix_log_level` (`Level`), INDEX `ix_log_executiontime` (`ExecutionTime`) ) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8; |
CREATE TABLE `my_site`.`log` ( `ID` int(10) unsigned NOT NULL auto_increment, `Date` datetime NOT NULL, `Thread` varchar(32) NOT NULL, `Context` varchar(10) NOT NULL, `Level` varchar(10) NOT NULL, `Logger` varchar(512) NOT NULL, `Method` varchar(200) default NULL, `Parameters` varchar(8000) default NULL, `Message` varchar(1000) NOT NULL, `Exception` varchar(4000) default NULL, `ExecutionTime` decimal(14,4) default NULL, PRIMARY KEY (`ID`), INDEX `ix_log_level` (`Level`), INDEX `ix_log_executiontime` (`ExecutionTime`) ) ENGINE=InnoDB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8;
The only interesting thing here is the “ExecutionTime” column. I added this because in this case I am logging to MySQL, and MySQL doesn’t store the millisecond portion of Date/Times. Seems it would be easier anyway to just log the time rather than try to connect start and finish entries (you could also do it in a single entry, as shown here). The reason I didn’t do this is because I wanted to be able to split the table into 3 (start, finish, and exception entries) to get as good an idea as I could what is happening at any given time.
Another thing to note here is that I added a column for parameter name/value combinations and the method name. log4net has a built-in conversion pattern for determining the method name, but it will not work for me because I plan to wrap log4net in a separate static helper class, in case I ever want to change the logging solution behind the scenes. I also read on log4net’s Pattern Layout docs that getting any kind of information about the caller from log4net is very slow, because it generates a call stack to read the information from. That is one hell of a warning, they might as well just put police tape around those methods. So I will take my chances getting this info from PostSharp!
Next is to configure log4net. Added an xml file called log4net.config to the top-level directory in the project. Something like this ought to do:
XML | |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 | <?xml version="1.0" encoding="utf-8" ?> <log4net> <!-- How to set up secondary appender (bufferless) for Exceptions only? --> <!-- Log4Net Appender Settings--> <root> <level value="All" /> <appender-ref ref="ADONetAppender" /> </root> <appender name="ADONetAppender" type="log4net.Appender.ADONetAppender"> <bufferSize value="10"/> <lossy value="false"/> <connectionType value="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"/> <connectionString value="Server=999.99.443.206;Database=my_site; Uid=someuser;Pwd=welcome1;"/> <commandText value="INSERT INTO Log (Date,Thread,Level,Logger,Message,Method,Parameters,Exception,Context,ExecutionTime) VALUES (?log_date, ?thread, ?log_level, ?logger, ?message, ?method_name, ?parameters, ?exception, ?context, ?execution_time)"/> <parameter> <parameterName value="log_date"/> <dbType value="DateTime"/> <layout type="log4net.Layout.RawTimeStampLayout"/> </parameter> <parameter> <parameterName value="thread"/> <dbType value="String"/> <size value="32"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%t"/> </layout> </parameter> <parameter> <parameterName value="log_level"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%p"/> </layout> </parameter> <parameter> <parameterName value="context"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%x"/> </layout> </parameter> <parameter> <parameterName value="logger"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%c"/> </layout> </parameter> <parameter> <parameterName value="message"/> <dbType value="String"/> <size value="1000"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%m"/> </layout> </parameter> <parameter> <parameterName value="exception"/> <dbType value="String"/> <size value="4000"/> <layout type="log4net.Layout.ExceptionLayout"/> </parameter> <parameter> <parameterName value="method_name"/> <dbType value="String"/> <size value="200"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{method_name}"/> </layout> </parameter> <parameter> <parameterName value="execution_time"/> <dbType value="Decimal"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{execution_time}"/> </layout> </parameter> <parameter> <parameterName value="parameters"/> <dbType value="String"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{parameters}"/> </layout> </parameter> </appender> </log4net> |
<?xml version="1.0" encoding="utf-8" ?> <log4net> <!-- How to set up secondary appender (bufferless) for Exceptions only? --> <!-- Log4Net Appender Settings--> <root> <level value="All" /> <appender-ref ref="ADONetAppender" /> </root> <appender name="ADONetAppender" type="log4net.Appender.ADONetAppender"> <bufferSize value="10"/> <lossy value="false"/> <connectionType value="MySql.Data.MySqlClient.MySqlConnection, MySql.Data"/> <connectionString value="Server=999.99.443.206;Database=my_site; Uid=someuser;Pwd=welcome1;"/> <commandText value="INSERT INTO Log (Date,Thread,Level,Logger,Message,Method,Parameters,Exception,Context,ExecutionTime) VALUES (?log_date, ?thread, ?log_level, ?logger, ?message, ?method_name, ?parameters, ?exception, ?context, ?execution_time)"/> <parameter> <parameterName value="log_date"/> <dbType value="DateTime"/> <layout type="log4net.Layout.RawTimeStampLayout"/> </parameter> <parameter> <parameterName value="thread"/> <dbType value="String"/> <size value="32"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%t"/> </layout> </parameter> <parameter> <parameterName value="log_level"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%p"/> </layout> </parameter> <parameter> <parameterName value="context"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%x"/> </layout> </parameter> <parameter> <parameterName value="logger"/> <dbType value="String"/> <size value="512"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%c"/> </layout> </parameter> <parameter> <parameterName value="message"/> <dbType value="String"/> <size value="1000"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%m"/> </layout> </parameter> <parameter> <parameterName value="exception"/> <dbType value="String"/> <size value="4000"/> <layout type="log4net.Layout.ExceptionLayout"/> </parameter> <parameter> <parameterName value="method_name"/> <dbType value="String"/> <size value="200"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{method_name}"/> </layout> </parameter> <parameter> <parameterName value="execution_time"/> <dbType value="Decimal"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{execution_time}"/> </layout> </parameter> <parameter> <parameterName value="parameters"/> <dbType value="String"/> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%property{parameters}"/> </layout> </parameter> </appender> </log4net>
Nothing really special there, except for the additional parameters we added that I didn’t see on most of the vanilla demos. One thing to note is the conversionPattern we used for the custom properties, “%property{PROPERTY_NAME}” as it can be very handy if you want to set custom parameters. There’s also a special “ErrorLog” that writes to a flat file without using a buffer, for errors only. This is so that if there is a fatal error in the application, the exceptions leading up to it are not lost. Onward. Next thing we need to do is ensure that log4net is configured when we start up the application. There are two ways to do this:
I first used AssemblyInfo.cs like so:
C# | |
1 | [assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)] |
[assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]
But found I could also use the Application_start method like this:
C# | |
1 2 3 4 5 | protected void Application_Start() { RegisterRoutes(RouteTable.Routes); log4net.Config.XmlConfigurator.Configure(new System.IO.FileInfo(HttpContext.Current.Server.MapPath("log4net.config"))); } |
protected void Application_Start() { RegisterRoutes(RouteTable.Routes); log4net.Config.XmlConfigurator.Configure(new System.IO.FileInfo(HttpContext.Current.Server.MapPath("log4net.config"))); }
I have not yet decided which I like better, but I lean towards the second method because the first just feels a bit dirty. So feel free to pick the one you like best.
Now that this is done, the fun can begin. First thing I did was set up a little helper class, so that I don’t have calls to log4net all over the place. Besides returning a log4net.ILog to be used in writing entries, this class will have a few methods to use to Add/Remove parameters from the ThreadContext’s Properties and NDC Stack. This class will look like this:
C# | |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 | using System; using System.Collections.Generic; using System.Linq; using System.Web; using log4net; [System.Diagnostics.DebuggerStepThrough] public static class Logging { /// <summary>Log an Informational Message</summary> public static void Info(String message) { LogManager.GetLogger("root").Info(message); } /// <summary>Log an Error Message</summary> public static void Error(String message, Exception ex) { //for errors, use the ErrorLog that will write to a flat file (bufferless) rather than database (buffered) LogManager.GetLogger("ErrorLogger").Error(message, ex); } /// <summary>Insert a parameter to MDC</summary> public static void SetParameter(String name, String value) { ThreadContext.Properties[name] = value; } /// <summary>Remove parameter from MDC</summary> public static void RemoveParameter(String name) { ThreadContext.Properties.Remove(name); } /// <summary>Add another context to NDC</summary> public static void PushContext(Object obj) { ThreadContext.Stacks["NDC"].Push(obj.ToString()); } /// <summary>Clear all contexts from NDC</summary> public static void ClearContext() { ThreadContext.Stacks["NDC"].Clear(); } /// <summary>Remove top context from NDC</summary> public static void PopContext() { ThreadContext.Stacks["NDC"].Pop(); } /// <summary>Set Execution time parameter (null for zero)</summary> public static void SetExecutionTime(DateTime? current) { Double execution_time_milliseconds = 0; if (current != null) { DateTime start; if (DateTime.TryParse(ThreadContext.Properties["start_time"].ToString(), out start)) { Int64 execution_time_ticks = (current.Value - start).Ticks; execution_time_milliseconds = (execution_time_ticks * 1.00 / TimeSpan.TicksPerMillisecond); } } ThreadContext.Properties["execution_time"] = execution_time_milliseconds; } /// <summary>Store context-specific start time for sharing across methods (within a thread)</summary> public static void SetStartTime() { ThreadContext.Properties["start_time"] = DateTime.Now.ToString(); } } |
using System; using System.Collections.Generic; using System.Linq; using System.Web; using log4net; [System.Diagnostics.DebuggerStepThrough] public static class Logging { /// <summary>Log an Informational Message</summary> public static void Info(String message) { LogManager.GetLogger("root").Info(message); } /// <summary>Log an Error Message</summary> public static void Error(String message, Exception ex) { //for errors, use the ErrorLog that will write to a flat file (bufferless) rather than database (buffered) LogManager.GetLogger("ErrorLogger").Error(message, ex); } /// <summary>Insert a parameter to MDC</summary> public static void SetParameter(String name, String value) { ThreadContext.Properties[name] = value; } /// <summary>Remove parameter from MDC</summary> public static void RemoveParameter(String name) { ThreadContext.Properties.Remove(name); } /// <summary>Add another context to NDC</summary> public static void PushContext(Object obj) { ThreadContext.Stacks["NDC"].Push(obj.ToString()); } /// <summary>Clear all contexts from NDC</summary> public static void ClearContext() { ThreadContext.Stacks["NDC"].Clear(); } /// <summary>Remove top context from NDC</summary> public static void PopContext() { ThreadContext.Stacks["NDC"].Pop(); } /// <summary>Set Execution time parameter (null for zero)</summary> public static void SetExecutionTime(DateTime? current) { Double execution_time_milliseconds = 0; if (current != null) { DateTime start; if (DateTime.TryParse(ThreadContext.Properties["start_time"].ToString(), out start)) { Int64 execution_time_ticks = (current.Value - start).Ticks; execution_time_milliseconds = (execution_time_ticks * 1.00 / TimeSpan.TicksPerMillisecond); } } ThreadContext.Properties["execution_time"] = execution_time_milliseconds; } /// <summary>Store context-specific start time for sharing across methods (within a thread)</summary> public static void SetStartTime() { ThreadContext.Properties["start_time"] = DateTime.Now.ToString(); } }
Ok so now we know how we are going to do the logging. Now, time to go through and add calls to this logging code throughout our application right? Not exactly. Lets take a look how post sharp comes in. We’ll want to extend the class “OnMethodBoundaryAspect” found in PostSharp.Laos. Use of this class will allow us to weave code into our application at compile time that will execute at various points during method execution (if the class has been tagged with the attribute we are about to create). For this exercise we are concerned with overriding the OnEntry, OnExit, and OnException methods. Their purposes ought to be pretty straight forward. I also added a method to take the method’s parameter values and build it into a string like “[param1 = A][param2 = B]”. The code for this looks like so:
C# | |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 | using System; using System.Collections.Generic; using System.Linq; using PostSharp.Laos; using System.Collections; [Serializable] [System.Diagnostics.DebuggerStepThrough] public class LoggableAttribute : OnMethodBoundaryAspect { public override void OnEntry(MethodExecutionEventArgs event_args) { Logging.SetStartTime(); Logging.SetExecutionTime(null); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); //for analysis, we want to be able to identify individual executions event_args.MethodExecutionTag = Guid.NewGuid(); Logging.PushContext(event_args.MethodExecutionTag); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.Info("Called " + event_args.Method); } public override void OnExit(MethodExecutionEventArgs event_args) { Logging.SetExecutionTime(DateTime.Now); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); Logging.Info("Finished " + event_args.Method); Logging.PopContext(); } public override void OnException(MethodExecutionEventArgs event_args) { Logging.SetExecutionTime(DateTime.Now); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); Logging.Error("Error Encountered in " + event_args.Method, event_args.Exception); } //helpers private static String ParametersToString(MethodExecutionEventArgs event_args) { String output = ""; if (event_args.GetReadOnlyArgumentArray() != null) { for (int i = 0; i < event_args.GetReadOnlyArgumentArray().Length; i++) { output += String.Format("[{0} = {1}]", event_args.Method.GetParameters()[i].Name, event_args.GetReadOnlyArgumentArray()[i]); } } return output; } } |
using System; using System.Collections.Generic; using System.Linq; using PostSharp.Laos; using System.Collections; [Serializable] [System.Diagnostics.DebuggerStepThrough] public class LoggableAttribute : OnMethodBoundaryAspect { public override void OnEntry(MethodExecutionEventArgs event_args) { Logging.SetStartTime(); Logging.SetExecutionTime(null); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); //for analysis, we want to be able to identify individual executions event_args.MethodExecutionTag = Guid.NewGuid(); Logging.PushContext(event_args.MethodExecutionTag); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.Info("Called " + event_args.Method); } public override void OnExit(MethodExecutionEventArgs event_args) { Logging.SetExecutionTime(DateTime.Now); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); Logging.Info("Finished " + event_args.Method); Logging.PopContext(); } public override void OnException(MethodExecutionEventArgs event_args) { Logging.SetExecutionTime(DateTime.Now); Logging.SetParameter("parameters", ParametersToString(event_args)); Logging.SetParameter("method_name", event_args.Method.Name); Logging.SetParameter("class_name", event_args.Instance.GetType().ToString()); Logging.Error("Error Encountered in " + event_args.Method, event_args.Exception); } //helpers private static String ParametersToString(MethodExecutionEventArgs event_args) { String output = ""; if (event_args.GetReadOnlyArgumentArray() != null) { for (int i = 0; i < event_args.GetReadOnlyArgumentArray().Length; i++) { output += String.Format("[{0} = {1}]", event_args.Method.GetParameters()[i].Name, event_args.GetReadOnlyArgumentArray()[i]); } } return output; } }
Pretty simple, considering what it does. Now that we’ve gone through all this effort to set things up, we can see where the magic happens. It seems like a lot of work, but this is where we get the payoff. Find a controller in your project, such as the default home controller. And just add your attribute to it:
C# | |
1 2 3 4 5 6 7 8 9 10 11 12 | [HandleError] [Loggable] public class HomeController : Controller { public ActionResult Index() { ViewData["Title"] = "Page Title"; ViewData["Message"] = "Hey LessThanDotters!"; return View(); } } |
[HandleError] [Loggable] public class HomeController : Controller { public ActionResult Index() { ViewData["Title"] = "Page Title"; ViewData["Message"] = "Hey LessThanDotters!"; return View(); } }
Now, the “[Loggable]” attribute is all that you need to add to any class that you want logging to take place on the three method boundaries that we wrote code for (there may be some limitations, but I’m not aware of them yet). You can add it on a method-by-method basis as well. If you want to stop logging a certain class/method, just remove the attribute. Its’ really that easy.
I’m sure I will find some problems with this approach eventually (first try and all), and I will update with those as I find them. Or if anything is immediately apparent, please point it out in the comments!
Sorry this post was so heavy on the code, I just thought it was really cool and wanted to share. Hopefully it gives you your own ideas for ways to use the PostSharp library.
Have fun!
16 Comments
I think the IP address 999.99.443.206 is wrong 🙂
Just kidding, great post, I will have to try it out…why did you not use PostgreSQL it has the timestamp dataype which goes down all the way to 1 microsecond
Thanks Denis. I have a free MySQL database with my web host, figured I’d use it. I’ve actually gotten quite fond of it (especially ON DUPLICATE KEY UPDATE), but it’ll never take SQL Server’s place in my heart 🙂
I’ve never used PostgreSQL but I suppose I should give it a look one of these days.
When I made games using PHP and mysql I would store milliseconds as a separate column, then string that together with DATETIME to give the user his score. I would order these separately on the page using a few IF statements so it looked right.
I saw this on the twitters today: http://code.google.com/p/postsharp-user-plugins/wiki/Log4PostSharp
Probably a better alternative in most cases (not sure for this one, since I needed to manually calculate execution time within aspect code)
Brill 🙂
One point though. If I put the Loggable attribute on my MVC controller base class, I get:
Called Void OnActionExecuting(System.Web.Mvc.ActionExecutingContext)
rather than the Action method name…
Any ideas why this might be?
Cheers,
Jon
do you use log4postsharp ?
Andrei, I haven’t used log4postsharp, but it does look very promising. If I need this again, I plan to use it (assuming I can get it running with PostSharp 1.5 / mono)
Jon, sorry I didn’t see this comment but I’m not sure what could cause your problem with the base controller. Take it you weren’t overriding OnActionExecuting in your class 😉 If I get a chance I’ll look into this.
Hello Alex,
Thanks for such a grate example. I have implemented your code in my application and it works well, one thing though, it is taking much time to insert record in db as around 2-3 thousands records enter during login process and more for other events. Will you please tell me how can i make it faster. Actually I m implementing it in MVC. My problem is i want to create a log of what actions are slowing us down for the whole site and let those events build up for 2-3 days. Then group by action, and get an average time to process, and see what the major issues are in the application. Please help
me on this
Hmm, I would start by trying to increase the buffer size log4net uses (this will minimize round trips to the database)
What I see here, is tons of logging code lines. This I don’t think is a good practice.
I think you may be missing the point Saeed. It seems like a lot of code (though not a lot more than it’d take to get something you can explicitly call) but it saves you from writing even a single method call in places you need logging. It also makes it easy to implement wholesale changes in your logging behavior without needing to change method signatures all over the place. In large systems, this benefit is not trivial.
Great tutorial. Curious if you have an updated code base for the latest release? Code is throwing errors for latest build of PostSharp.
Can you please let me know will this work in case of my application run under the load balancer environment. I actually want log all errors in file.
I don’t see why it wouldn’t – as mentioned above this is not going to work with the latest version of PostSharp though, and I am not going to update because it is not free anymore. I’m fairly sure the approach with new version would be similar.
Great article, very helpful. It may help some to note that more recent versions of MySQL (5.6.4+ I think) now do support milliseconds. Change your date creation to Date(3) and MySQL will store the date as ‘2015-01-01 13:45:30.258’. It has to be when the table is created, you can’t do it with ALTER TABLE…
We’re already having success with log4net and MySQL separately. Hadn’t really had the cycles to try combining them yet…
fat-fingered, that should have been datetime(3)
….