C# MVC Logging method execution and performance

Question

There are many other posts regarding the recording of method execution time (for example through postsharp, through action filters, or through a custom method attribute).

So to record the time for a method to complete is relatively straightforward at this point.

What I am looking to do however, is to get more fine-grained performance metrics on a per-request basis utilizing, for example, session id to track all operations that occured for a given request - and the time elapses for all of them, not just the parent (i.e. action controller) method.

For example, I would like to be able to do something like:

namespace MvcApplication1.Controllers
{
    public class ProductController : Controller
    {
        //record start of method 
        public ActionResult Index()
        {
            //record start of service1.method call
            var data = service1.method();
            //store total time of service1.method call

            //record start of db call
            var objects = db.select(obj).where(id=0)
            //store total time of db call

            return View();
        }
        //record total time of method
    }
}

Ideally I want to link all of these operations (the parent method, the service call and the db call) together - the most likely candidate would be through the session id - but that means that each call would need access to the session id.

From what I've read, the best way of accomplishing this would be to utilize a method attribute to record the parent performance time, and then some sort of custom library function to store the various timing of the calls (probably using nlog to record).

What I am asking for are opinions on what the best way (if at all possible) to accomplish the above?

Am I missing something with any third party libraries that exist - i.e. does Unity or Postsharp provide this functionality (or some other library)?

Is it possible to link all of these records via the session id? For example, I don't see how to via postsharp (1) store individual method calls INSIDE the MVC action, and (2) to pass variables between calls.

Answer 1

According to your question, you need to log all operations related for a request. I'll provide my point of view, I hope that would be useful.

If you'll use an existing framework or not depends of many reasons, for now I'll focus on and custom implementation.

First, to accomplish this issue you need a log structure:

using System;

public enum LogEntryType
{
    Event,
    Message,
    Warning,
    Error
}

public class LogEntry
{
    public int? LogEntryID { get; set; }

    public int? LogEntryType { get; set; }

    public DateTime? EntryDate { get; set; }

    public TimeSpan? ElapsedTime { get; set; }

    public string Key { get; set; }

    public string Description { get; set; }
}

Next, you need to create a logger object and invoke on each point you want to log, for example:

namespace MvcApp.Controllers
{
    public class ProductController : Controller
    {
        protected ILogger Logger;

        public ProductController(ILogger logger;)
        {
            Logger = logger;
        }

        public ActionResult Index()
        {
            Logger.Write(LogEntry.Event, Server.SessionID, "Start of '{0}' action call", "Index");


            var serviceStopwatch = Stopwatch.StartNew();

            Logger.Write(LogEntry.Task, Server.SessionID, "Start of '{0}' task's execution", "GetData");

            var data = service.GetData();

            serviceStopwatch.Stop();

            Logger.Write(LogEntry.Task, Server.SessionID, serviceStopwatch.Elapsed, "End of '{0}' task's execution", "GetData");


            var dbCallStopwatch = Stopwatch.StartNew();

            Logger.Write(LogEntry.Task, Server.SessionID, "Start of '{0}' db call", "GetObjects");

            var objects = repository.GetObjects();

            dbCallStopwatch.Stop();

            Logger.Write(LogEntry.Task, Server.SessionID, dbCallStopwatch.Elapsed, "End of '{0}' db call", "GetObjects");


            Logger.Write(LogEntry.Event, Server.SessionID, "End of '{0}' action call", "Index");

            return View();
        }
    }
}

In the code above, we take the key's value from server's session id (automatic generated) for group all entries.

The Logger.Write method's signatures should be something like these:

public void Write(LogEntryType logEntryType, string key, string message, params string[] args)
{
    var item = new LogEntry
    {
        LogEntryType = (int?)logEntryType,
        EntryDate = DateTime.Now,
        Key = key,
        Description = string.Format(message, args)
    };

    // Code for save log entry to text file, database, send email if it's an error, etc.
}

public void Write(LogEntryType logEntryType, string key, TimeSpan elapsedTime, string message, params string[] args)
{
    var item = new LogEntry
    {
        LogEntryType = (int?)logEntryType,
        EntryDate = DateTime.Now,
        ElapsedTime = elapsedTime,
        Key = key,
        Description = string.Format(message, args)
    };

    // Code for save log entry to text file, database, send email if it's an error, etc.
}

Usually in real business applications, we need to have workflow definitions for execution metrics and other stuffs, but at this moment I don't know how complex do you want to develop this feature.

If you add all logger's calls in your required point and save all of them into a database (sql or nosql), next you would extract all information about one session id events.

As you can see above, there are some log entry type definitions: warning and errors, suppose that you add try-catch block for error handling, inside of catch block if there is an exception you can log it:

Logger.Write(LogEntry.Error, Server.SessionID, "There was an error on '{0}' task. Details: '{1}'", "Index", ex.Message);

As an additional point, it's better to implement async operations to avoid server blocking for requests.

If this answer makes sense we can improve the concepts, this is a basic idea how you can solve your issue.