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.