Views: 3430
Number of votes: 3
Average rating:

Light logging of time used in Controller and View

There are great tool available for logging user actions on your site like google analytic, but sometimes you want to know more about how much time a controller used, and how much time the view rendering took. If one creates a ActionFilterAttribute and tag your controller with it it’s possible to get that kind of information easy.

You tag your controller like this

    [TrackTimeActionFilter]
    public class SearchPageController : PageController<SearchPage>
    {

The you create a TrackTimeActionFilter

    public class TrackTimeActionFilter : ActionFilterAttribute
    {
        Stopwatch stopWatch0;
        Stopwatch stopWatch1;
        Stopwatch stopWatch2;
        public override void OnActionExecuting(ActionExecutingContext filterContext)
        {
            stopWatch0 = new Stopwatch();
            stopWatch1 = new Stopwatch();
            stopWatch0.Start();
            stopWatch1.Start();
        }
        public override void OnActionExecuted(ActionExecutedContext filterContext)
        {
            stopWatch1.Stop();
           
           // Log("OnActionExecuted", filterContext.RouteData);
        }
        public override void OnResultExecuting(ResultExecutingContext filterContext)
        {
            stopWatch2 = new Stopwatch();
            stopWatch2.Start();
        }
        public override void OnResultExecuted(ResultExecutedContext filterContext)
        {
            stopWatch0.Stop();
            stopWatch2.Stop();
            Log(filterContext.RouteData, stopWatch0.ElapsedMilliseconds, stopWatch1.ElapsedMilliseconds, stopWatch2.ElapsedMilliseconds, filterContext.HttpContext);

        }
      
        private void Log(RouteData routeData, long timeTotal, long timeController, long timeRenderView, HttpContextBase context)
        {
            var service = ServiceLocator.Current.GetInstance<ContentActionStoreService>();
            if (service.IsEnabled && !EPiServer.Editor.PageEditing.PageIsInEditMode)
            {
                try {

                    var add = CreateEntity(routeData);
                    if (add != null)
                    {
                        var userNameOrSessionId = context.Session.SessionID;
                        if (!string.IsNullOrEmpty(context.User.Identity.Name))
                            userNameOrSessionId = context.User.Identity.Name;
                        var ip = GetUsersIp(context.Request);
                        IGeolocationResult geo = null;
                        if (ip != IPAddress.None)
                            geo = GetCurrentUsersLocation(ip);
                        add.SiteReference = ContentReference.StartPage.ToReferenceWithoutVersion().ToString();
                        add.MachineName = System.Environment.MachineName;
                        add.TotalMilliSeconds = timeTotal;
                        add.ControllerMilliSeconds = timeController;
                        add.ViewMilliSeconds = timeRenderView;
                        add.Viewed = DateTime.Now;
                        add.IpAdress = "" + ip;
                        add.RawUrl = context.Request.RawUrl;
                        if (context.Request.UrlReferrer!=null)
                        {
                            add.UrlReferrer = "" + context.Request.UrlReferrer;
                            var url = new EPiServer.UrlBuilder(context.Request.UrlReferrer);
                            var fromContent = UrlResolver.Current.Route(new EPiServer.UrlBuilder(context.Request.UrlReferrer));
                            if (fromContent==null)
                                fromContent = UrlResolver.Current.Route(new EPiServer.UrlBuilder(context.Request.UrlReferrer.PathAndQuery));
                          
                            if (fromContent!=null)
                            {
                                add.ReferrerReferenceWithoutVersion = fromContent.ContentLink.ToReferenceWithoutVersion().ToString();
                                if (fromContent is ILocale && (fromContent as ILocale).Language!=null)
                                    add.ReferrerLanguageID = (fromContent as ILocale).Language.Name.ToLower();
                            }
                          
                        }
                           
                        add.QueryString = context.Request.Url.Query;
                        add.IsEditMode = EPiServer.Editor.PageEditing.PageIsInEditMode;
                        add.UserNameOrSessionId = userNameOrSessionId;

                        if (geo != null)
                        {
                            add.Region = geo.Region;
                            add.ContinentCode = geo.ContinentCode;
                            add.CountryCode = geo.CountryCode;
                            if (geo.Location != null)
                            {
                                add.Latitude = geo.Location.Latitude;
                                add.Longitude = geo.Location.Longitude;
                                add.HorizontalAccuracy = geo.Location.HorizontalAccuracy;
                            }
                        }

                        service.AddAndLazySave(add);

                    }
                }
                catch (System.Exception error)
                {
                    service.AddError(error);
                }

            }
        }
        protected static ContentActionEntity CreateEntity(RouteData routeData)
        {

            var nodeRef = "" + routeData.DataTokens["node"];
            ContentReference parsed;
            if (!ContentReference.TryParse(nodeRef, out parsed))
            {
                return null;
            }
            var result = new ContentActionEntity();
            result.ReferenceWithoutVersion = parsed.ToReferenceWithoutVersion().ToString();
            result.WorkdId = parsed.WorkID;
            result.ControllerName = "" + routeData.Values["controller"];
            result.ActionName = "" + routeData.Values["action"];

            result.LanguageID = "" + (routeData.Values["language"] ?? routeData.DataTokens["defaultLanguage"]);
            if (string.IsNullOrEmpty(result.LanguageID))
                result.LanguageID = ContentLanguage.PreferredCulture.Name;
            var currentNode = routeData.Values["currentContent"];
            if (currentNode is IContent)
            {
                result.ReferenceWithoutVersion += (currentNode as IContent).ContentLink.ToReferenceWithoutVersion().ToString();
                result.WorkdId += (currentNode as IContent).ContentLink.WorkID;
            }
            if (currentNode is ILocale)
            {
                result.LanguageID = (currentNode as ILocale).Language.Name;
            }

            return result;

        }
        protected IGeolocationResult GetCurrentUsersLocation(IPAddress ipAddress)
        {
            var geoLocationProvider = Geolocation.Provider as GeolocationProvider;

            return geoLocationProvider.Lookup(ipAddress);
        }
        protected IPAddress GetUsersIp(HttpRequestBase request)
        {


            if (request.ServerVariables["HTTP_X_FORWARDED_FOR"] != null)
                return IPAddress.Parse(request.ServerVariables["HTTP_X_FORWARDED_FOR"].ToString());

            if (request.UserHostAddress.Length != 0)
                return IPAddress.Parse(request.UserHostAddress);

            return IPAddress.None;
        }
    }

This code will create an object of type ContentActionEntity and save it to a store if we are not in edit modus. The object have different kind of attributes specified bellow.

[EPiServerDataStore(AutomaticallyRemapStore = true, AutomaticallyCreateStore = true)]
    public class ContentActionEntity : IDynamicData
    {
        public EPiServer.Data.Identity Id { get; set; }
        [EPiServerIgnoreDataMember]
        public bool IsSaved { get
            {
                if (Id == null)
                    return false;
                return true;
            }
        }
        [EPiServerDataIndex]
        public string SiteReference { get; set; }

        [EPiServerDataIndex]
        public string MachineName { get; set; }

        [EPiServerDataIndex]
        public string ReferenceWithoutVersion { get; set; }

        public int WorkdId { get; set; }
        [EPiServerDataIndex]
        public string LanguageID { get; set; }

        [EPiServerDataIndex]
        public bool IsEditMode { get; set; }

        [EPiServerDataIndex]
        public DateTime Viewed { get; set; }

        public long TotalMilliSeconds { get; set; }
        public long ControllerMilliSeconds { get; set; }
        public long ViewMilliSeconds { get; set; }

        public string UserNameOrSessionId { get; set; }

        public string QueryString { get; set; }

        public string ControllerName { get; set; }
        public string ActionName { get; set; }
   


        public string ContinentCode { get; set; }

        public string CountryCode { get; set; }
        public string Region { get; set; }

        public string IpAdress { get; set; }

        public double HorizontalAccuracy { get; set; }

        public double Latitude { get; set; }

        public double Longitude { get; set; }

        public string RawUrl { get; set; }
        public string UrlReferrer { get; set; }

        [EPiServerDataIndex]
        public string ReferrerReferenceWithoutVersion { get; set; }

        [EPiServerDataIndex]
        public string ReferrerLanguageID { get; set; }

        public GeoCoordinate GetLocation()
        {
            return new GeoCoordinate(Latitude, Longitude);
        }
        public string GetContinentName()
        {
            if (string.IsNullOrEmpty(ContinentCode))
                return "";
            var localizationService = ServiceLocator.Current.GetInstance<LocalizationService>();
            return localizationService.GetString("/shell/cms/visitorgroups/criteria/geographiclocation/continents/" + ContinentCode);
        }
        public string GetCountryName()
        {
            if (string.IsNullOrEmpty(CountryCode))
                return "";
            var localizationService = ServiceLocator.Current.GetInstance<LocalizationService>();
            return localizationService.GetString("/shell/cms/visitorgroups/criteria/geographiclocation/countries/" + CountryCode);
        }
        public IContent GetContent()
        {
            try {
                var pageRef = ContentReference.Parse(ReferenceWithoutVersion);
                var lang = new LanguageSelector(this.LanguageID);
                return EPiServer.DataFactory.Instance.Get<IContent>(pageRef, lang);
            }
            catch
            {
                return null;
            }
        }

        public MvcHtmlString GetPageName(string format)
        {
            try
            {
                var pageRef = ContentReference.Parse(ReferenceWithoutVersion);
                var lang = new LanguageSelector(this.LanguageID);
                var pathList = EPiServer.DataFactory.Instance.GetAncestors(pageRef).Where(p => p is SitePageData).Reverse().Select(p => p.Name);

                var paths =string.Join("/", pathList);
                var name = EPiServer.DataFactory.Instance.Get<IContent>(pageRef, lang).Name;

                return MvcHtmlString.Create(string.Format(format, paths, name));

            }
            catch
            {
                return MvcHtmlString.Create(string.Format(format, "Error " + ReferenceWithoutVersion + " [" + LanguageID + "]", ""));
            }
       
        }
    }

The servcie looks like this

    [ServiceConfiguration(ServiceType = typeof(ContentActionStoreService), Lifecycle = ServiceInstanceScope.Singleton)]
    public class ContentActionStoreService
    {
        public ContentActionStoreService()
        {
            var key = ConfigurationManager.AppSettings["ServereTimeInfo"];
            if (string.IsNullOrEmpty(key) || key.ToLower() == "true")
            {
                IsEnabled = true;
            }
        }
       
        DynamicDataStore ContentActionStore
        {
            get
            {
                return DynamicDataStoreFactory.Instance.GetStore(typeof(ContentActionEntity));
            }
        }
       
        List<ContentActionEntity> spool = new List<ContentActionEntity>();
        object lockObject = new object();
        public void AddAndLazySave(ContentActionEntity add)
        {
            Add(add);
            SaveTempItems(false);
            
        }
        public void SaveTempItems(bool always)
        {
            List<ContentActionEntity> saveItems = null;
            lock (lockObject)
            {
                if (spool.Count > 10 || always)
                {
                    saveItems = spool;
                    spool = new List<ContentActionEntity>();
                }
            }
            if (saveItems != null)
            {
                foreach (var item in saveItems)
                    ContentActionStore.Save(item);
            }
        }
        void Add(ContentActionEntity add)
        {
                      lock (lockObject)
            {
                spool.Add(add);
            }
        }
}

Then you can either create a view based on thees rows, or just to some SQL queries on the view. Either way it’s a easy and simple solution to find what controller actions or views that takes long time to execute.

Apr 12, 2016

henriknystrom
(By henriknystrom, 4/13/2016 1:40:31 AM)

Hi Anders,
have you tried using this in a production environment at all? Cause from a quick glance it looks like it contains a couple of things I would worry about doing in a logging method that gets called every time an action is processed. First of all the geolocation lookup can be quite resource intense and even more importantly I would be very vary of logging against a database, let alone the DDS in the Episerver database. And even if you only save it on every 10+ request, you still call the save method for each entry which means that the workload will be the same.

But then again, you intention might never have been to put this in production, but this might be good to point out to any readers.

Anders Hattestad
(By Anders Hattestad, 4/13/2016 9:14:08 AM)

Hi Henrik

This code is meant for finding out where there are any bottlenecks. So I will have this feature turn'ed on for some time to get some data to analyse.
We are talking about low volum web sites. like 10'-20' views pr month, so I'm not that worry to leave it on for a month.

But if you break it down the code have 2 parts.

One information gathering part, where the geo stuff is the most costly as you have pointed out. I was not aware that the Geolocation Lookup was not cached. Thank you for pointing that out.

The second part save's the data to a table. To save a item into the DDS don't cost that much. It's reading from the DDS that takes time. But if I would have this turned on at all times I would save it to a spesifc table or database. 

Jari Haapatalo
(By Jari Haapatalo, 4/13/2016 10:37:50 AM)

I find http://miniprofiler.com/ a usefull tool to measure time used in controllers.

K Khan
(By K Khan , 4/13/2016 1:22:09 PM)

Have you tried the Glimpse? http://play.getglimpse.com/ 

It provides hardened Security, so only you get to choose who can see what Glimpse data and when. It is lightweight & fast. Its unique architecture makes it faster and less resource intensive than traditional profilers so you never have to sacrifice performance. 

Once installed, Glimpse inspects web requests as they happen, providing insights and tooling that reduce debugging time and empower every developer to improve their web applications. Glimpse profiles key server side activities/actions and displays the timing of each in an easy to understand Gantt chart. Glimpse provides complete visibility into ASP.NET MVC's view resolution process, including file access paths. 

You can easily extend for EpiServer Specific Debugging.

Shamrez Iqbal
(By Shamrez Iqbal, 4/14/2016 11:48:29 AM)

I believe something like this is also possible with New Relic (and Application Insights)?

I'm not sure if it is as detailed (possibly in the paid version?) as Glimpse or the solution the author proposes.

Please login to comment.