15

I'm looking for a way to track how long it took for a page to be generated by the server. I know I can use Trace to track this but I need a way to display this per page.

Its ASP.Net MVC 2

LiamB
  • 18,243
  • 19
  • 75
  • 116

3 Answers3

16

You can implement it like a ActionFilterAttribute

[AttributeUsage(AttributeTargets.Class, AllowMultiple = false)]
public class LoggingAttribute : ActionFilterAttribute
{
    private readonly Stopwatch _sw;

    public LoggingAttribute()
    {
        _sw = new Stopwatch();
    }

    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
        _sw.Start();
        Debug.WriteLine("Beginning executing: " + GetControllerAndActionName(filterContext.ActionDescriptor));
    }

    public override void OnActionExecuted(ActionExecutedContext filterContext)
    {
        _sw.Stop();
        var ms = _sw.ElapsedMilliseconds;

        Debug.WriteLine("Finishing executing: " + GetControllerAndActionName(filterContext.ActionDescriptor));
        Debug.WriteLine("Time elapsed: "+ TimeSpan.FromMilliseconds(ms).TotalSeconds);
    }

    private string GetControllerAndActionName(ActionDescriptor actionDescriptor)
    {
        return actionDescriptor.ControllerDescriptor.ControllerName + " - " + actionDescriptor.ActionName;
    }
}

Decorate every controller or action-method with it and voila, it spit outs the text in debug.

EDIT: If you want to print it on the page you could add this snippet to the OnActionExecuted method

if(filterContext.Result is ViewResult) { //Make sure the request is a ViewResult, ie. a page
  ((ViewResult) filterContext.Result).ViewData["ExecutionTime"] = ms; //Set the viewdata dictionary
}

Now you have the executiontime saved in ViewData and can access it in the page.. I usually put it in the masterpage like this

<!-- The page took <%= ViewData["ExecutionTime"] %> ms to execute -->
Kenny Eliasson
  • 2,047
  • 15
  • 23
  • Decorate every controller or action-method is a bit of a pain as we have a lot (Pretty big project) - anyway we can make this work site wide without making such a large change? – LiamB Dec 01 '09 at 15:50
  • 4
    In my projeect all my controllers inherits from a BaseController. So I just decorate the basecontroller, which in turn "decorates" all action-methods being executed. – Kenny Eliasson Dec 01 '09 at 15:53
  • 2
    Its Pretty good approach, its just worth mentioning that this actually track the Controller life time, and not the total Request life time. – JOBG Dec 01 '09 at 16:50
  • @Omar, from my understanding a Request begins when an Action is "Executing" and ends when an Action is "Executed". What would be the request life time otherwise? – Omar Dec 02 '09 at 02:01
  • @Baddie, probably things like an HttpModule wouldn't be measured. But I don't know for sure. – Kenny Eliasson Dec 02 '09 at 08:09
  • @Baddie - Before the Controller get Invoked, there are some other Handlers that take action first (like System.Web.Mvc.MvcHandler), here are some good resources about ASP MVC Life cycle: http://stackoverflow.com/questions/460145/what-is-the-page-lifecycle-of-an-asp-net-mvc-page-compared-to-asp-net-webforms/460165#460165. – JOBG Dec 02 '09 at 14:46
  • 1
    @Pino - With ASP.NET MVC3 you can add the attribute to the GlobalFiltersCollection during the `Application_Start` handler to avoid decorating every class/action with it. – Justin Rusbatch Apr 11 '11 at 21:47
  • 2
    Shouldn't the elapsed time be calculated i OnResultExecuted instead of OnActionExecuted? – BigJoe714 Jan 30 '14 at 18:13
  • I agree with @BigJoe714 – Kat Lim Ruiz May 10 '14 at 03:52
  • Or track both? :) Anyways nowadays I just use MvcMiniProfiler which is great! – Kenny Eliasson May 10 '14 at 07:55
14

Yep the Derin Suggestion is the standard Way to do it in an ASP.NEt application, i would just suggest add an if so it does not interfere with non-HTML responses: EDIT: added complete implementation

public class PerformanceMonitorModule : IHttpModule
{

    public void Init(HttpApplication context)
    {
        context.PreRequestHandlerExecute += delegate(object sender, EventArgs e)
        {
            //Set Page Timer Star
            HttpContext requestContext = ((HttpApplication)sender).Context;
            Stopwatch timer = new Stopwatch();
            requestContext.Items["Timer"] = timer;
            timer.Start();
             };
        context.PostRequestHandlerExecute += delegate(object sender, EventArgs e)
        {

            HttpContext httpContext = ((HttpApplication)sender).Context;
            HttpResponse response = httpContext.Response;
            Stopwatch timer = (Stopwatch)httpContext.Items["Timer"];
            timer.Stop();

            // Don't interfere with non-HTML responses
            if (response.ContentType == "text/html")
            {
                double seconds = (double)timer.ElapsedTicks / Stopwatch.Frequency;
                string result_time = string.Format("{0:F4} sec ", seconds);
                RenderQueriesToResponse(response,result_time);
            }
        };
    }
    void RenderQueriesToResponse(HttpResponse response, string result_time)
    {
        response.Write("<div style=\"margin: 5px; background-color: #FFFF00\"");
        response.Write(string.Format("<b>Page Generated in "+ result_time));
        response.Write("</div>");
    }
    public void Dispose() { /* Not needed */ }
}

you can also add some style to it...

And remember to register your Module in WebConfig inside httpModules Section:

  <add name="Name" type="namespace, dll"/>

For a Complete Reference about this check the Pro ASP.NET MVC Framework by Steven Sanderson - Chapter 15 - Performance, Monitoring Page Generation Times.

EDIT:(comment @Pino) Here is the example for my project: alt text http://www.diarioplus.com/files/pictures/example_performance.JPG

JOBG
  • 4,544
  • 4
  • 26
  • 47
  • Thanks - works well except This seems to output AFTER the

    element which breaks my page :( suggestions?

    – LiamB Dec 01 '09 at 15:46
  • This is added (append) as part of the response, it may not be after the HTML closing tag. – JOBG Dec 01 '09 at 15:58
  • I edit my post with a sample img, i already have a project running and test it, i don't know why Darin said its after the HTML..?, maybe he referred to another implementation. – JOBG Dec 01 '09 at 16:10
  • Can you post full example? the code at the moment is displaying below the

    tag.

    – LiamB Dec 02 '09 at 08:10
4

It will depend on where you want to include this information. For example you could write an http handler that will display the render time after the </html> tag:

public class RenderTimeModule : IHttpModule
{
    public void Init(HttpApplication context)
    {
        context.BeginRequest += (sender, e) =>
        {
            var watch = new Stopwatch();
            var app = (HttpApplication)sender;
            app.Context.Items["Stopwatch"] = watch;
            watch.Start();
        };

        context.EndRequest += (sender, e) =>
        {
            var app = (HttpApplication)sender;
            var watch = (Stopwatch)app.Context.Items["Stopwatch"];
            watch.Stop();
            var ts = watch.Elapsed;
            string elapsedTime = String.Format("{0} ms", ts.TotalMilliseconds);
            app.Context.Response.Write(elapsedTime);
        };
    }

    public void Dispose()
    {
    }
}

If you want to display render time somewhere in the middle of the html page then this render time will not account for the total page render time.

Darin Dimitrov
  • 1,023,142
  • 271
  • 3,287
  • 2,928