2

I want to log the request processing time for Asp.Net MVC application. I can get 'time-taken' from IIS logs but this time includes the network time taken to send the response back to client browser. I am only interested in the time taken to preocess the request by asp.net worker process.

I have an option of writting a HttpModule but I can not control the order of running of HttpModules.

Update - 1:

I need to log the processing-time for all the requests. The requests are slow only for some users which I am not able to reproduce when I request the page. 'MiniProfiler' and 'Glimpse' will not give me the 'procssing-time' for all the requests by different users.

Update - 2:

Filters will give me 'time-taken' only by Controller. It will not cover the 'time-taken' by various 'HttpModules' pluged in into the Asp.Net app

Amitabh
  • 59,111
  • 42
  • 110
  • 159
  • Ok, what's the meaning of "I can not control the order of running of HttpModules", HttpModules are executed in the order in which they were registered. http://forums.asp.net/t/1101427.aspx – Donald Oct 20 '15 at 08:25
  • @Donald: There are many HttpModules which are inherited from applicationHost.config. I dont want to touch that as there are many other web app deployed on the same server – Amitabh Oct 20 '15 at 09:01
  • as you can see in link, all httpmodules that are defined in the machine.config file, will be executed first. If you don't want it, you can remove it. Or if you want to re-order it, remove it, add your own, then add it back in your Web.config. – Donald Oct 20 '15 at 09:21

2 Answers2

1

One simple option would be to use something like Miniprofiler. There's documentation that shows you how to tie it into MVC properly.

However, if this type of metric is truly meaningful to track long term, I'd suggest looking into something like New Relic, or any other APM (application performance monitoring) solution.

You can also check out Glimpse. It doesn't so much log as just show you all the pertinent statistics as you browse around. It's also more suited to development than running on a production server, though you can potentially run it in production if you choose.

Chris Pratt
  • 232,153
  • 36
  • 385
  • 444
1

You can create a filter to intercept action execution time.

 public class ActionTiming :ActionFilterAttribute {
    private static readonly ILog Logger = LogManager.GetLogger("TimingLogger");
    private string controllerName = string.Empty;
    private string actionName = string.Empty;

    private Stopwatch intertime = Stopwatch.StartNew();
    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
        intertime.Restart();
        controllerName = filterContext.RouteData.Values["controller"].ToString();
        actionName = filterContext.RouteData.Values["action"].ToString();
        var message = string.Format("{0} controller: {1} action: {2}", "OnActionExecuting", controllerName, actionName);
        Logger.Info(message);

    }

    public override void OnResultExecuted(ResultExecutedContext filterContext)
    {

        var message = string.Format("{0} controller: {1} action: {2}, time (ms): {3}", "OnResultExecuted", controllerName, actionName, intertime.ElapsedMilliseconds);
        Logger.Info(message);
    }


}

Then, you can register this filter globally in Application_Start or use it as attribute.

Donald
  • 534
  • 1
  • 10
  • 18
  • Apologizes but i need to downvote. It is not guaranteed that the instantiation of the actionFilter will happen for each request, making this solution unreliable. Use 'actionContext.Request.Properties' instead. https://stackoverflow.com/a/28885099/1754152, https://stackoverflow.com/a/22553930/1754152 – Mario Feb 25 '21 at 05:24