What’s the Holy Grail of Application Profiling? Well, it should be…
- Rich Data – Giving us detailed logging ability, recording which method is being called, where it’s being called from, when it starts, when it stops, overall execution time –and- if any exceptions are thrown.
- Low Impact – Adds just a fraction of a second to the methods being profiled, highly performant. ( MS-Word says “performant” isn’t a word – Wiktionary and I disagree <grin> )
- Minimal Code – Follows the D.R.Y. principle ( Don’t Repeat Yourself), less code == easier maintenance and generally better performance.
- Loosely Coupled – Easy to add to a project, with little to no code added to the existing code.
So… How do we create the Holy Grail of Application Profiling? We use a very cool technology called AOP ( Aspect Oriented Programming ).
AOP complements Object-Oriented Programming (OOP), giving us even more tools that increase modularity and allowing us to elegantly handle “crosscutting concerns” such as logging, exception handling and other common challenges. One of the most popular AOP tools is PostSharp (http://www.sharpcrafters.com/), which allows us to “IL Weave” our profiling code ( the act of adding code as IL instructions into the assemblies at compile time )! Sweet…
So let’s start at the end – what do we get?
We’ll if you start a brand new “MVC 4 Web Project” in Visual Studio – by adding a couple references and ONE line in your AssemblyInfo.cs file…
[assembly: ProfileAspect(AttributeTargetTypes = "ProfileWeb.Controllers.*")]
We can start logging to SQL and, for example, easily extract really rich data on pages hit and their load times such as…
Nice… Not bad for ONE line of code… Intrigued? I know you would be… 🙂
Download the Profiler Code (44 MB)
I’ve included demo code / SQL, etc for your review – but here are the highlights of how to build the AOP “aspect” for profiling.
So my project layout is as shown…
“Common.All” is my shared library that has Helper methods and code Extensions, etc – it’s my “code it, then forget how you coded it – and just call the cool methods you already made” library. As always, it could use some additional house keeping, but it’s a great help in all my projects – feel free to use what you want out if it for your other projects. And if you have cool code to add – send it to me, love to see it!
“Common.Aspects” is a very clean way of extracting all of the AOP “aspect” code out so we can include it cleanly in this and any other project.
“Common.Logging” is my ( not unexpected ) logging library – nice to have it wrapped up in it’s own library so you can use your favorite flavor of logger – I’m using NLog – which I add to the NuGet package installer. Note, you need to copy the NLog.config file into each of your projects for which you are logging – gives you the flexibility to have different project logged with different levels of detail.
“Common.Models” are some model classes that I needed to share between libraries – specifically the “Profile” model that gets used in both the “Common.Aspects” and the “Common.Logging” libraries.
“ProfileConsole” is the C# Console app – that we use for testing impact through timing – play with your settings, logging configuration, etc – then use this to get an easy measurable way ( as I will show ) to see the impact of those settings.
“ProfileWeb” is a straight out of the box MVC4 “Internet” Web project. This shows really how little code it takes to utilize the powerful feature of everything else that we’ve built!!!
There is a lot of great code in the “Common” projects – but we’ll just hit the highlights and let you then explorer the rest on your own. But lets start by looking at the AOP code! Note, I’m pretty OCD about including comments – mainly so when I come back in 6 months, _I_ remember why it was done this way – so I’ll leave those comments to explain the code. 🙂
1: using Common.All.Helpers;
2: using Common.Logging;
3: using Common.Models;
4: using PostSharp.Aspects;
5: using System;
6:
7: namespace Common.Aspects
8: {
9: [Serializable]
10: public class ProfileAspect : OnMethodBoundaryBaseAspect
11: {
12: /// <summary>
13: /// Method executed <b>before</b> the body of methods to which this aspect is applied.
14: /// </summary>
15: /// <param name="args">Event arguments specifying which method
16: /// is being executed, which are its arguments, and how should the execution continue
17: /// after the execution of <see cref="M:PostSharp.Aspects.IOnMethodBoundaryAspect.
18: /// OnEntry(PostSharp.Aspects.MethodExecutionArgs)" />.</param>
19: public override void OnEntry(MethodExecutionArgs args)
20: {
21: //----------------------------------------------------------------------
22: // Ignore specified methods
23: //----------------------------------------------------------------------
24: if (IgnoreMethods(args)) return;
25:
26: //----------------------------------------------------------------------
27: // Create a new instance Profiler, start the stopwatch and persist to state
28: // Use the Fluent design pattern for .Start() as defined in our Profiler model
29: //----------------------------------------------------------------------
30: Profiler profile = new Profiler(AspectBoundaryType.OnEntry, args).Start();
31:
32: //----------------------------------------------------------------------
33: // Get the values from the calling AssemblyInfo.cs file attributes
34: // Use our customr AssemblyInfoCalling() class - that crawls the Stack
35: // so we can get this information in as Loosely Coupled manner as possible
36: //----------------------------------------------------------------------
37: AssemblyInfoCalling assembly = new AssemblyInfoCalling();
38: profile.Application.Name = assembly.Title;
39: profile.Application.Version = assembly.VersionFull;
40: profile.Location.Name = assembly.Location;
41: args.MethodExecutionTag = profile;
42:
43: //----------------------------------------------------------------------
44: // Log the profiler object to our custom Logger class
45: //----------------------------------------------------------------------
46: _log = new Log();
47: _log.Profile(profile);
48: }
49:
50: /// <summary>
51: /// Method executed <b>after</b> the body of methods to which this aspect is applied,
52: /// but only when the method successfully returns (i.e. when no exception flies out
53: /// the method.).
54: /// </summary>
55: /// <param name="args">Event arguments specifying which method
56: /// is being executed and which are its arguments.</param>
57: public override void OnSuccess(MethodExecutionArgs args)
58: {
59: //----------------------------------------------------------------------
60: // Ignore specified methods
61: //----------------------------------------------------------------------
62: if (IgnoreMethods(args)) return;
63:
64: //----------------------------------------------------------------------
65: // Get the instance of Profiler, update the values and save back to persistant state
66: //----------------------------------------------------------------------
67: Profiler profile = (Profiler)args.MethodExecutionTag;
68: args.MethodExecutionTag = profile.Update(AspectBoundaryType.OnSuccess, args);
69:
70: //----------------------------------------------------------------------
71: // Log the profiler
72: //----------------------------------------------------------------------
73: _log.Profile(profile);
74: }
75:
76: /// <summary>
77: /// Method executed <b>after</b> the body of methods to which this aspect is applied,
78: /// even when the method exists with an exception (this method is invoked from
79: /// the <c>finally</c> block).
80: /// </summary>
81: /// <param name="args">Event arguments specifying which method
82: /// is being executed and which are its arguments.</param>
83: public override void OnExit(MethodExecutionArgs args)
84: {
85: //----------------------------------------------------------------------
86: // Ignore specified methods
87: //----------------------------------------------------------------------
88: if (IgnoreMethods(args)) return;
89:
90: //----------------------------------------------------------------------
91: // Get the instance of Profiler, stop the stopwatch and update values
92: //----------------------------------------------------------------------
93: Profiler profile = (Profiler)args.MethodExecutionTag;
94: profile.Update(AspectBoundaryType.OnExit, args).Stop();
95:
96: //----------------------------------------------------------------------
97: // Log the profiler
98: //----------------------------------------------------------------------
99: _log.Profile(profile);
100: }
101:
102: /// <summary>
103: /// Method executed <b>after</b> the body of methods to which this aspect is applied,
104: /// in case that the method resulted with an exception.
105: /// </summary>
106: /// <param name="args">Event arguments specifying which method
107: /// is being executed and which are its arguments.</param>
108: public override void OnException(MethodExecutionArgs args)
109: {
110: //----------------------------------------------------------------------
111: // Get the instance of Profiler, stop the stopwatch and update values
112: //----------------------------------------------------------------------
113: Profiler profile = (Profiler)args.MethodExecutionTag;
114: profile.Update(AspectBoundaryType.OnException, args);
115:
116: //----------------------------------------------------------------------
117: // Log the profiler
118: //----------------------------------------------------------------------
119: _log.Profile(profile);
120: }
121:
122: /// <summary>
123: /// Ignores these methods when profiling - add to these as you see fit, may be
124: /// a better way of excluding these through the assembly reference in PostSharp -
125: /// will have to check with the PostSharp devs. :) But for now - this keeps
126: /// some of the unwanted "chatter" out of our data
127: /// </summary>
128: /// <param name="args">The args.</param>
129: /// <returns></returns>
130: private static bool IgnoreMethods(MethodExecutionArgs args)
131: {
132: switch (args.Method.Name)
133: {
134: //----------------------------------------------------------------------
135: // Don't want to see the timing for the Controller's constructors
136: //----------------------------------------------------------------------
137: case ".ctor":
138: return true;
139: default:
140: return false;
141: }
142: }
143: }
144: }
So PostSharp will take the above code – and “weave” it into the code – so using ILSpy (free) or JustDecompile (also free, and my favorite) – you can see a with and without AOP.
This is “without” – nice, clean – you see what it’s trying to do ( which isn’t much in this case ) – but if you had to code all of the do do profiling / exception handling, etc – that would be a maintenance nightmare – to the point where it just wouldn’t get done.
1: public ActionResult Index()
2: {
3: ViewBag.Message = "Modify this template to jump-start your ASP.NET MVC application.";
4:
5: return View();
6: }
And this is what we see when we decompile the same method – wow… Glad I didn’t have to add all that great code to every method manually…!
1: public ActionResult Index()
2: {
3: ActionResult returnValue = null;
4: Arguments empty = Arguments.Empty;
5: MethodExecutionArgs methodExecutionArg = new MethodExecutionArgs(this, empty);
6: MethodBase methodBase = HomeController.HomeController.m1;
7: methodExecutionArg.Method = methodBase;
8: HomeController.HomeController.a23.OnEntry(methodExecutionArg);
9: if (methodExecutionArg.FlowBehavior != FlowBehavior.Return)
10: {
11: try
12: {
13: try
14: {
15: ((dynamic)base.ViewBag).Message = "Modify this template to jump-start your ASP.NET MVC application.";
16: ActionResult actionResult = base.View();
17: returnValue = actionResult;
18: methodExecutionArg.ReturnValue = returnValue;
19: HomeController.HomeController.a23.OnSuccess(methodExecutionArg);
20: returnValue = (ActionResult)methodExecutionArg.ReturnValue;
21: }
22: catch (Exception exception1)
23: {
24: Exception exception = exception1;
25: methodExecutionArg.Exception = exception;
26: HomeController.HomeController.a23.OnException(methodExecutionArg);
27: switch (methodExecutionArg.FlowBehavior)
28: {
29: case FlowBehavior.Continue:
30: {
31: methodExecutionArg.Exception = null;
32: break;
33: }
34: case FlowBehavior.Return:
35: {
36: methodExecutionArg.Exception = null;
37: returnValue = (ActionResult)methodExecutionArg.ReturnValue;
38: break;
39: }
40: case FlowBehavior.ThrowException:
41: {
42: throw methodExecutionArg.Exception;
43: }
44: default:
45: {
46: throw;
47: }
48: }
49: }
50: }
51: finally
52: {
53: methodExecutionArg.ReturnValue = returnValue;
54: HomeController.HomeController.a23.OnExit(methodExecutionArg);
55: returnValue = (ActionResult)methodExecutionArg.ReturnValue;
56: }
57: }
58: else
59: {
60: returnValue = (ActionResult)methodExecutionArg.ReturnValue;
61: }
62: return returnValue;
63: }
So other highlights – in the “Common.Models” library – the “Profiler” class contains all the information we’re capturing – but also nicely contains “fluent” patterned methods for Start(), Stop() and Update() – also does a nice job of overriding the ToString() so we can cleanly write out a message just by calling it’s ToString() method.
1: public class Profiler
2: {
3: #region | Properties |
4:
5: public AspectBoundaryType BoundaryType { get; set; }
6: public DateTime? dateEnd { get; set; }
7: public DateTime? dateStart { get; set; }
8: public string MethodDeclaringTypeName { get; set; }
9: public string MethodName { get; set; }
10: public List<string> MethodParameters { get; set; }
11: public bool MethodParametersExist { get; set; }
12: public object ReturnValue { get; set; }
13: public Exception Exception { get; set; }
14: public ProfilerLocation Location { get; set; }
15: public ProfilerApplication Application { get; set; }
16:
17: private Stopwatch Stopwatch { get; set; }
18: public long EllapsedTime
19: {
20: get
21: {
22: return this.dateEnd != null ? this.Stopwatch.ElapsedMilliseconds : 0;
23: }
24: }
25:
26: #endregion
27:
28: #region | Constructors |
29:
30: /// <summary>
31: /// Initializes a new instance of the <see cref="Profiler"/> class.
32: /// </summary>
33: public Profiler(AspectBoundaryType boundaryType, MethodExecutionArgs args)
34: {
35: this.BoundaryType = boundaryType;
36: if (args.Method.DeclaringType != null) this.MethodDeclaringTypeName = args.Method.DeclaringType.Name;
37: this.MethodName = args.Method.Name;
38:
39: if (this.Location == null) this.Location = new ProfilerLocation();
40: if (this.Application == null) this.Application = new ProfilerApplication();
41: }
42:
43: #endregion
44:
45: #region | Methods |
46:
47: /// <summary>
48: /// Starts this timers.
49: /// </summary>
50: /// <returns>Fluent pattern instance</returns>
51: public Profiler Start()
52: {
53: this.Stopwatch = Stopwatch.StartNew();
54: this.dateStart = DateTime.Now;
55:
56: return this;
57: }
58:
59: /// <summary>
60: /// Stops this timers.
61: /// </summary>
62: /// <returns>Fluent pattern instance</returns>
63: public Profiler Stop()
64: {
65: this.Stopwatch.Stop();
66: this.dateEnd = DateTime.Now;
67:
68: return this;
69: }
70:
71: /// <summary>
72: /// Updates the profile values
73: /// </summary>
74: /// <param name="boundaryType">Type of the boundary.</param>
75: /// <param name="args">The args.</param>
76: /// <returns>Fluent pattern instance</returns>
77: public Profiler Update(AspectBoundaryType boundaryType, MethodExecutionArgs args)
78: {
79: this.BoundaryType = boundaryType;
80: if (args.Method.ContainsGenericParameters)
81: {
82: this.MethodParameters = args.Method.GetGenericArguments().Select(t => t.Name).ToList();
83: }
84: this.MethodParametersExist = args.Method.ContainsGenericParameters;
85: this.ReturnValue = args.ReturnValue;
86:
87: if (this.BoundaryType == AspectBoundaryType.OnException)
88: {
89: if (args.Exception != null)
90: {
91: this.Exception = args.Exception;
92: }
93: }
94:
95: return this;
96: }
97:
98: /// <summary>
99: /// Returns a <see cref="System.String" /> that represents this instance.
100: /// </summary>
101: /// <returns>
102: /// A <see cref="System.String" /> that represents this instance.
103: /// </returns>
104: public override string ToString()
105: {
106: StringBuilder sb = new StringBuilder();
107:
108: if (MethodDeclaringTypeName != null)
109: {
110: sb.Append(string.Format("{0}.{1}", this.MethodDeclaringTypeName, this.MethodName));
111: }
112:
113: sb.Append(string.Format(" | {0}", this.BoundaryType));
114:
115: if (ReturnValue != null)
116: {
117: sb.Append(string.Format(" | Returns = {0}", this.ReturnValue));
118: }
119:
120: if ((this.Stopwatch != null) && (this.dateEnd != null))
121: {
122: sb.Append(string.Format(" | {0} ms", this.Stopwatch.ElapsedMilliseconds));
123: }
124:
125: if (this.dateEnd != null)
126: {
127: sb.Append(string.Format(" | {0}", this.dateStart.ToCustomDateTimeDetailed(this.dateEnd)));
128: }
129:
130: if (this.MethodParametersExist)
131: {
132: sb.Append(string.Format(" | <{0}>", this.MethodParameters.ToDelimString(",")));
133: }
134:
135: return sb.ToString();
136: }
137:
138: #endregion
139: }
If you haven’t extended NLog or your favorite flavor of logger – this is a pretty nice pattern on which to build.
On top of the usual Log.Info(), Log.Warn(), Log.Error(), etc – added the ability Log.Profile() and simply pass in the object above. Note – for NLog to be able to log the values – we pass them in through the GlobalDiagnosticsContext.Set() method. See the NLog.config file below to see the other side of this communication.
1: [Serializable]
2: public class Log : ILog
3: {
4: #region | Properties |
5:
6: public Logger Logger { get; set; }
7:
8: #endregion
9:
10: #region | Constructors |
11:
12: /// <summary>
13: /// Initializes a new instance of the <see cref="Log"/> class.
14: /// </summary>
15: public Log()
16: {
17: //----------------------------------------------------------------------
18: // Initialize
19: //----------------------------------------------------------------------
20: this.Logger = LogManager.GetLogger("Logging");
21:
22: //----------------------------------------------------------------------
23: // Clear the additional logging info
24: //----------------------------------------------------------------------
25: GlobalDiagnosticsContext.Clear();
26: }
27:
28: public Log(System.Web.HttpContext context) : this()
29: {
30: string ip = GetIPAddress(context);
31: GlobalDiagnosticsContext.Set("LocationIp", ip);
32: }
33:
34: #endregion
35:
36: #region | Public Methods |
37:
38: /// <summary>
39: /// Logs the Profile properties
40: /// </summary>
41: /// <param name="profile">The profile.</param>
42: public void Profile(Profiler profile)
43: {
44: //----------------------------------------------------------------------
45: // Set the logging info for profile
46: //----------------------------------------------------------------------
47: this.Logger = LogManager.GetLogger(profile.MethodName);
48: GlobalDiagnosticsContext.Set("DateStart", profile.dateStart.ToDateTimeHighPrecision());
49: GlobalDiagnosticsContext.Set("DateEnd", profile.dateEnd.ToDateTimeHighPrecision());
50: GlobalDiagnosticsContext.Set("ExecutionTime", profile.EllapsedTime.ToString(CultureInfo.InvariantCulture));
51: GlobalDiagnosticsContext.Set("BoundaryType", profile.BoundaryType.ToString());
52: GlobalDiagnosticsContext.Set("SourceParent", profile.MethodDeclaringTypeName);
53: GlobalDiagnosticsContext.Set("Source", profile.MethodName);
54: GlobalDiagnosticsContext.Set("SourceParams", profile.MethodParameters.ToDelimString(","));
55: GlobalDiagnosticsContext.Set("SourceReturn", (profile.ReturnValue == null ? string.Empty : profile.ReturnValue.ToString()));
56: GlobalDiagnosticsContext.Set("ExceptionMessage", (profile.Exception == null ? string.Empty : profile.Exception.MessageFull()));
57: GlobalDiagnosticsContext.Set("ExceptionType", (profile.Exception == null ? string.Empty : profile.Exception.GetType().ToString()));
58: GlobalDiagnosticsContext.Set("StackTrace", (profile.Exception == null ? string.Empty : profile.Exception.StackTrace));
59: GlobalDiagnosticsContext.Set("Location", profile.Location.Name);
60: GlobalDiagnosticsContext.Set("LocationIp", profile.Location.Ip);
61: GlobalDiagnosticsContext.Set("LocationUser", profile.Location.User);
62: GlobalDiagnosticsContext.Set("Application", profile.Application.Name);
63: GlobalDiagnosticsContext.Set("ApplicationVersion", profile.Application.Version);
64:
65: //----------------------------------------------------------------------
66: // Write message to debug console
67: //----------------------------------------------------------------------
68: Debug.WriteLine(profile.ToString());
69:
70: //----------------------------------------------------------------------
71: // Log as different log levels based on boundary type
72: //----------------------------------------------------------------------
73: switch (profile.BoundaryType)
74: {
75: case AspectBoundaryType.OnEntry:
76: case AspectBoundaryType.OnSuccess:
77: this.Logger.Trace(profile.ToString());
78: break;
79:
80: case AspectBoundaryType.OnExit:
81: this.Logger.Info(profile.ToString());
82: break;
83:
84: case AspectBoundaryType.OnException:
85: this.Logger.Error(profile.ToString(), profile.Exception);
86: break;
87: }
88: }
89:
90: /// <summary>
91: /// Logs the Trace message
92: /// </summary>
93: /// <param name="message">The message.</param>
94: public void Trace(string message)
95: {
96: Initialize();
97:
98: #if DEBUG
99: Debug.WriteLine(message);
100: #endif
101: this.Logger.Trace(message);
102: }
103:
104: /// <summary>
105: /// Logs the Info message
106: /// </summary>
107: /// <param name="message">The message.</param>
108: public void Info(string message)
109: {
110: Initialize();
111:
112: #if DEBUG
113: Debug.WriteLine(message);
114: #endif
115: this.Logger.Info(message);
116: }
117:
118: /// <summary>
119: /// Logs the Warning message
120: /// </summary>
121: /// <param name="message">The message.</param>
122: public void Warn(string message)
123: {
124: Initialize();
125:
126: #if DEBUG
127: Debug.WriteLine(message);
128: #endif
129: this.Logger.Warn(message);
130: }
131:
132: /// <summary>
133: /// Logs the Error message
134: /// </summary>
135: /// <param name="message">The message.</param>
136: public void Error(string message)
137: {
138: Initialize();
139:
140: #if DEBUG
141: Debug.WriteLine(message);
142: #endif
143: this.Logger.Error(message);
144: }
145:
146: /// <summary>
147: /// Logs the Error message
148: /// </summary>
149: /// <param name="message">The message.</param>
150: /// <param name="exception">The exception.</param>
151: public void Error(string message, Exception exception)
152: {
153: Initialize();
154:
155: SetExceptionProperties(exception);
156:
157: #if DEBUG
158: Debug.WriteLine(message);
159: #endif
160: this.Logger.ErrorException(message, exception);
161: }
162:
163: public void Error(Exception exception)
164: {
165: Initialize();
166:
167: SetExceptionProperties(exception);
168:
169: #if DEBUG
170: Debug.WriteLine(exception.MessageFull());
171: #endif
172: this.Logger.ErrorException(exception.MessageFull(), exception);
173: }
174:
175: #endregion
176:
177: #region | Private Methods |
178:
179: /// <summary>
180: /// Initialization for logging methods
181: /// </summary>
182: private static void Initialize()
183: {
184: //----------------------------------------------------------------------
185: // Get the method and class
186: //----------------------------------------------------------------------
187: string methodName = GetInfo.CurrentMethod.Name(3);
188: string className = GetInfo.CurrentClass.Name(3);
189: GlobalDiagnosticsContext.Set("SourceParent", className);
190: GlobalDiagnosticsContext.Set("Source", methodName);
191:
192: //----------------------------------------------------------------------
193: // Get the calling assembly properties, need to set the level to 5 to get the correct assembly
194: //----------------------------------------------------------------------
195: AssemblyInfoCalling assembly = new AssemblyInfoCalling(5);
196: GlobalDiagnosticsContext.Set("Application", assembly.Title);
197: GlobalDiagnosticsContext.Set("ApplicationVersion", assembly.VersionFull);
198: GlobalDiagnosticsContext.Set("Location", assembly.Location);
199: }
200:
201: private static void SetExceptionProperties(Exception exception)
202: {
203: GlobalDiagnosticsContext.Set("ExceptionMessage", (exception == null ? string.Empty : exception.MessageFull()));
204: GlobalDiagnosticsContext.Set("StackTrace", (exception == null ? string.Empty : exception.StackTrace));
205: GlobalDiagnosticsContext.Set("ExceptionType", (exception == null ? string.Empty : exception.GetType().ToString()));
206: }
207:
208: //TODO: Validate that this works for non-local testing
209: protected string GetIPAddress(System.Web.HttpContext context)
210: {
211: string ipAddress = context.Request.ServerVariables["HTTP_X_FORWARDED_FOR"];
212:
213: if (!string.IsNullOrEmpty(ipAddress))
214: {
215: string[] addresses = ipAddress.Split(',');
216: if (addresses.Length != 0)
217: {
218: return addresses[0];
219: }
220: }
221:
222: return context.Request.ServerVariables["REMOTE_ADDR"];
223: }
224:
225: #endregion
226: }
So NLog is obviously very powerful right out of the gate – allowing us to write to a database, file, webservice, email, etc – and allows us to tell it to do so asynchronously with just a setting. So, while I’m in favor of using the best tool for the job – often I write my own – but in this case once you figure out some of the nuances of passing in your own values, there is little to no reason to not use NLog. I scoured the internet for best configuration ideas of NLog.config files – and this is the culmination of what I’ve learned so far. Use it and make it even better, then send me the updates. 🙂 Note – obviously, change the connection string to your database.
1: <?xml version="1.0" encoding="utf-8" ?>
2: <nlog autoReload="true"
3: throwExceptions="true"
4: internalLogLevel="Info"
5: internalLogToConsole="false"
6: internalLogFile="${basedir}/nlog.txt"
7: xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
8: xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
9:
10: <!--
11: See http://nlog-project.org/wiki/Configuration_file
12: for information on customizing logging rules and outputs.
13: -->
14:
15: <targets async="true">
16: <default-wrapper xsi:type="RetryingWrapper"/>
17: <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
18: layout="${longdate} ${uppercase:${level}} ${message}" />
19: <target xsi:type="File" name="f2" fileName="c:/temp/logs/${shortdate}.log"
20: layout="${longdate} ${uppercase:${level}} ${message}" />
21:
22: <target xsi:type="Database" name="databaseprofiler">
23:
24: <dbProvider>sqlserver</dbProvider>
25:
26: <!-- database connection parameters -->
27: <!-- alternatively you could provide a single 'connectionstring' parameter -->
28: <connectionString>Data Source=localhost;Initial Catalog=WebProfiler;Integrated Security=SSPI</connectionString>
29:
30: <commandText>
31: INSERT INTO [WebProfiler].[dbo].[LogProfiler]
32: ([LogLevel]
33: ,[DateStart]
34: ,[DateEnd]
35: ,[ExecutionTime]
36: ,[BoundaryType]
37: ,[SourceParent]
38: ,[Source]
39: ,[SourceParams]
40: ,[SourceReturn]
41: ,[Message]
42: ,[ExceptionType]
43: ,[ExceptionMessage]
44: ,[StackTrace]
45: ,[UserName]
46: ,[WindowsIdenty]
47: ,[MachineName]
48: ,[Location]
49: ,[LocationIp]
50: ,[LocationUser]
51: ,[Application]
52: ,[ApplicationVersion])
53: VALUES
54: (@LogLevel
55: ,@DateStart
56: ,@DateEnd
57: ,@ExecutionTime
58: ,@BoundaryType
59: ,@SourceParent
60: ,@Source
61: ,@SourceParams
62: ,@SourceReturn
63: ,@Message
64: ,@ExceptionType
65: ,@ExceptionMessage
66: ,@StackTrace
67: ,@UserName
68: ,@WindowsIdenty
69: ,@MachineName
70: ,@Location
71: ,@LocationIp
72: ,@LocationUser
73: ,@Application
74: ,@ApplicationVersion)
75: </commandText>
76:
77: <parameter name="@LogLevel" layout="${level}" />
78: <parameter name="@DateStart" layout="${gdc:DateStart}" />
79: <parameter name="@DateEnd" layout="${gdc:DateEnd}" />
80: <parameter name="@ExecutionTime" layout="${gdc:ExecutionTime}" />
81: <parameter name="@BoundaryType" layout="${gdc:BoundaryType}" />
82: <parameter name="@SourceParent" layout="${gdc:SourceParent}" />
83: <parameter name="@Source" layout="${gdc:Source}" />
84: <parameter name="@SourceParams" layout="${gdc:SourceParams}" />
85: <parameter name="@SourceReturn" layout="${gdc:SourceReturn}" />
86: <parameter name="@Message" layout="${message}" />
87: <parameter name="@ExceptionType" layout="${gdc:ExceptionType}" />
88: <parameter name="@ExceptionMessage" layout="${gdc:ExceptionMessage}" />
89: <parameter name="@StackTrace" layout="${gdc:StackTrace}" />
90: <parameter name="@UserName" layout="${environment:variable=UserName}" />
91: <parameter name="@WindowsIdenty" layout="${windows-identity}" />
92: <parameter name="@MachineName" layout="${machinename}" />
93: <parameter name="@Location" layout="${gdc:Location}" />
94: <parameter name="@LocationIp" layout="${gdc:LocationIp}" />
95: <parameter name="@LocationUser" layout="${gdc:LocationUser}" />
96: <parameter name="@Application" layout="${gdc:Application}" />
97: <parameter name="@ApplicationVersion" layout="${gdc:ApplicationVersion}" />
98:
99: </target>
100:
101: </targets>
102: <rules>
103: <!--<logger name="*" minlevel="Trace" writeTo="f" />-->
104: <!--<logger name="*" minlevel="Trace" writeTo="f2" />-->
105:
106: <logger name="*" minlevel="Trace" writeTo="databaseprofiler" />
107: </rules>
108: </nlog>
Here is the SQL side….
1: CREATE TABLE [dbo].[LogProfiler](
2: [Id] [bigint] IDENTITY(1,1) NOT NULL,
3: [LogLevel] [varchar](50) NOT NULL,
4: [DateCreated] [datetime] NOT NULL,
5: [DateStart] [datetime] NULL,
6: [DateEnd] [datetime] NULL,
7: [ExecutionTime] [int] NULL,
8: [BoundaryType] [varchar](50) NULL,
9: [SourceParent] [varchar](200) NULL,
10: [Source] [varchar](200) NULL,
11: [SourceParams] [varchar](max) NULL,
12: [SourceReturn] [varchar](max) NULL,
13: [Message] [varchar](max) NULL,
14: [ExceptionType] [varchar](200) NULL,
15: [ExceptionMessage] [varchar](max) NULL,
16: [StackTrace] [varchar](max) NULL,
17: [UserName] [varchar](100) NULL,
18: [WindowsIdenty] [varchar](100) NULL,
19: [MachineName] [varchar](100) NULL,
20: [Location] [varchar](200) NULL,
21: [LocationIp] [varchar](100) NULL,
22: [LocationUser] [varchar](200) NULL,
23: [Application] [varchar](200) NULL,
24: [ApplicationVersion] [varchar](50) NULL,
25: CONSTRAINT [PK_LogProfiler] PRIMARY KEY CLUSTERED
26: (
27: [Id] ASC
28: )WITH (PAD_INDEX = OFF, STATISTICS_NORECOMPUTE = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS = ON, ALLOW_PAGE_LOCKS = ON) ON [PRIMARY]
29: ) ON [PRIMARY]
30:
31: GO
32:
33: ALTER TABLE [dbo].[LogProfiler] ADD CONSTRAINT [DF_LogProfiler_DateCreated] DEFAULT (getdate()) FOR [DateCreated]
34: GO
And here is the simple SQL query to get the data that we saw at the very beginning of this article!
1: SELECT SourceParent, Source, SUM(ExecutionTime) AS Total,
2: MAX(ExecutionTime) AS MaxTime,
3: MIN(ExecutionTime) AS MinTime,
4: AVG(ExecutionTime) AS AvgTime,
5: Count(*) As Count FROM dbo.LogProfiler WHERE BoundaryType = 'OnExit'
6: AND Application = 'ProfileWeb'
7: GROUP BY SourceParent, Source
8: ORDER BY SourceParent, Source
Last thing in this EPIC blog posting ( what do you expect to be able to create the “Holy Grail”? ) is timing / testing to quantify the impact on code to get profiling information.
In the “ProfileConsole” project – we have a simple loop calling and timing a method in which we specify a specific Sleep() time.
1: class Program
2: {
3: static void Main(string[] args)
4: {
5: const int runTimes = 100;
6:
7: Log log = new Log();
8: log.Info("start");
9:
10: Stopwatch sw = new Stopwatch();
11: sw.Start();
12: for (int i = 0; i < runTimes; i++)
13: {
14: TestMethod1();
15: Console.WriteLine("Run Times: {0}", i);
16: //log.Trace(string.Format("Run Times: {0}", i));
17: }
18: sw.Stop();
19:
20: log.Info("end");
21:
22: var ms = sw.ElapsedMilliseconds;
23: Console.WriteLine("Run Times: {0}, Total Time: {1}, Avg Time: {2}", runTimes, ms, ms / runTimes);
24: Console.ReadLine();
25: }
26:
27: private static void TestMethod1()
28: {
29: Thread.Sleep(100);
30: }
31: }
Running this, here is the data I collected… The results show a very manageable impact of just 10 ms when running the Aspect and writing to the Database – but NOT writing to a file. Writing to the file kicked it up to 28 ms – generally unnecessary cost there.
Notes – for my Visual Studio projects I use NuGet extensively – if you haven’t used it -do so-, it allows for libraries, code, etc to be easily added to Visual Studio projects.
I found that adding the PostSharp reference through NuGet to be the most reliable and maintainable way to keep a consistent version of PostSharp across projects.
Just right click on your project –> Click on “Manage NuGet Packages…” –> Select “Online” –> type “PostSharp” in text box in upper right and “Install”
So let’s see how we stacked up against our “Holy Grail” criteria…
- Rich Data – DONE! Gave us detailed logging, recording
which method is being called, where it’s being called from, when it starts, when
it stops, overall execution time –and- if any exceptions are thrown! - Low Impact – DONE! Our timing data shows that we are just adding ~10ms overhead, most excellent considering the Rich Data we’re getting!
- Minimal Code – DONE! It’s D.R.Y. ( Don’t Repeat
Yourself), no code has been harmed in the making of these classes. :p Don’t have the same code repeated over and over and over – very maintainable. - Loosely Coupled – DONE! I’d call one line in the AssemblyInfo.cs and a couple references pretty Loosely Coupled. 🙂
Very nice – Indiana Jones eat your heart out…
As always, love to get feedback and suggestions on how to make this even better… Have work to do, adding unit tests, etc. But what a great start!
…Lance
Download the Profiler Code (44 MB)
I really like this, and I plan to try it out. Do you have any plans to add your project to the main NuGet.org repository?
Awesome – would love to hear that it works for your projects, do get back to me on that. As to NuGet — that’s a great idea – haven’t done so before, will add to my ToDo list to investigate. 🙂 Thanks.