Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Why is my code apparently calling LocalDataStoreMgr.GetNamedDataSlot?

When our ASP.NET website is under heavy load, every now and then, one of the servers will just go wild and use 100% CPU without responding at all. When I run stackdump.exe on the running process, I see that practically all threads are ending in the method LocalDataStoreMgr.GetNamedDataSlot. Some stacks look as if our own code calls into GetNamedDataSlot, others show HttpApplication.ExecuteStep or HttpWriter.Write doing it. Here is a snippet from the stack dump:

OS Thread Id:9232
  System.LocalDataStoreMgr.GetNamedDataSlot(System.LocalDataStoreMgrN/A)
  System.Web.HttpApplication.ExecuteStep(ASP.global_asaxSystem.Web.HttpApplication+AsyncEventExecutionStepSystem.Boolean&)
  System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Web.HttpApplication+PipelineStepManagerN/A)
  System.Web.HttpApplication.BeginProcessRequestNotification(N/AN/AN/A)
  System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.HttpRuntimeSystem.Web.Hosting.IIS7WorkerRequestSystem.Web.HttpContext)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(N/ASystem.IntPtrN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(N/AN/AN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(N/AN/AN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(N/AN/AN/AN/A)

OS Thread Id:15308
  System.LocalDataStoreMgr.GetNamedDataSlot(System.LocalDataStoreMgrN/A)
  System.Web.HttpWriter.Write(System.Web.HttpWriterSystem.String)
  System.Web.HttpWriter.Write(N/AN/A)
  ASP.views_shared_advertcat_setadvertinformation_ascx.__Render__control1(N/AN/AN/A)
  System.Web.UI.Control.RenderChildrenInternal(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderChildrenInternal(N/AN/AN/A)
  System.Web.Mvc.ViewPage.Render(System.Web.Mvc.ViewUserControl+ViewUserControlContainerPageN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Page.ProcessRequestMain(System.Web.Mvc.ViewUserControl+ViewUserControlContainerPageSystem.BooleanSystem.Boolean)
  System.Web.UI.Page.ProcessRequest(System.Web.Mvc.ViewUserControl+ViewUserControlContainerPageN/ASystem.Boolean)
  System.Web.UI.Page.ProcessRequest(N/AN/AN/A)
  System.Web.UI.Page.ProcessRequest(System.Web.Mvc.ViewUserControl+ViewUserControlContainerPage)
  System.Web.UI.Page.ProcessRequest(N/AN/A)
  System.Web.Mvc.ViewPage.ProcessRequest(N/AN/A)
  System.Web.Mvc.ViewUserControl+ViewUserControlContainerPage.ProcessRequest(N/AN/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper+<>c__DisplayClass4.<Wrap>b__3(N/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper.Wrap(N/A)
  System.Web.HttpServerUtility.ExecuteInternal(System.Web.HttpServerUtilitySystem.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapperN/AN/AN/ASystem.Web.VirtualPathN/AN/ASystem.ExceptionSystem.String)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/AN/A)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/A)
  System.Web.Mvc.ViewPage.RenderView(N/AN/A)
  System.Web.Mvc.ViewUserControl.RenderView(N/AN/A)
  System.Web.Mvc.ViewResultBase.ExecuteResult(N/AN/A)
  System.Web.Mvc.ControllerActionInvoker+<>c__DisplayClass1a.<InvokeActionResultWithFilters>b__17(N/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Controllers.Shared.AdvertControllerSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(N/AN/AN/AN/A)
  System.Web.Mvc.Async.AsyncControllerActionInvoker+<>c__DisplayClass25.<BeginInvokeAction>b__22(System.Web.Mvc.Async.AsyncControllerActionInvoker+<>c__DisplayClass25N/A)
  System.Web.Mvc.Controller+<>c__DisplayClass1d.<BeginExecuteCore>b__18(N/AN/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.Mvc.Controller.EndExecuteCore(Funda.Web.Mvc.Controllers.Shared.AdvertControllerN/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.Mvc.MvcHandler+<>c__DisplayClass8.<BeginProcessRequest>b__3(System.Web.Mvc.MvcHandler+<>c__DisplayClass8N/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper+<>c__DisplayClass4.<Wrap>b__3(N/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper.Wrap(N/A)
  System.Web.HttpServerUtility.ExecuteInternal(System.Web.HttpServerUtilitySystem.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerAsyncWrapperN/AN/AN/ASystem.Web.VirtualPathN/AN/ASystem.ExceptionSystem.String)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/AN/A)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/A)
  System.Web.Mvc.Html.ChildActionExtensions.ActionHelper(N/AN/AN/AN/AN/A)
  ASP.views_homepage_homepage_aspx.__Render__control5(N/AN/AN/A)
  System.Web.UI.Control.RenderChildrenInternal(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  ASP.views_masterpages_homepage_master.__Render__control1(ASP.views_masterpages_homepage_masterSystem.Web.UI.HtmlTextWriterASP.views_masterpages_homepage_master)
  System.Web.UI.Control.RenderChildrenInternal(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderChildrenInternal(N/AN/AN/A)
  System.Web.Mvc.ViewPage.Render(ASP.views_homepage_homepage_aspxN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Control.RenderControl(N/AN/AN/A)
  System.Web.UI.Page.ProcessRequestMain(ASP.views_homepage_homepage_aspxSystem.BooleanSystem.Boolean)
  System.Web.UI.Page.ProcessRequest(ASP.views_homepage_homepage_aspxN/ASystem.Boolean)
  System.Web.UI.Page.ProcessRequest(N/AN/AN/A)
  System.Web.UI.Page.ProcessRequest(ASP.views_homepage_homepage_aspx)
  System.Web.UI.Page.ProcessRequest(N/AN/A)
  System.Web.Mvc.ViewPage.ProcessRequest(N/AN/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper+<>c__DisplayClass4.<Wrap>b__3(N/A)
  System.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapper.Wrap(N/A)
  System.Web.HttpServerUtility.ExecuteInternal(System.Web.HttpServerUtilitySystem.Web.Mvc.HttpHandlerUtil+ServerExecuteHttpHandlerWrapperN/AN/AN/ASystem.Web.VirtualPathN/AN/ASystem.ExceptionSystem.String)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/AN/A)
  System.Web.HttpServerUtility.Execute(N/AN/AN/AN/A)
  System.Web.Mvc.ViewPage.RenderView(N/AN/A)
  System.Web.Mvc.ViewResultBase.ExecuteResult(N/AN/A)
  System.Web.Mvc.ControllerActionInvoker+<>c__DisplayClass1a.<InvokeActionResultWithFilters>b__17(N/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Attributes.DataForGoogleAnalyticsAttributeSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Attributes.SetLanguageFromProfileAttributeSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Attributes.DataForLoginAttributeSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Attributes.DataForNotifyAttributeSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilter(Funda.Web.Mvc.Controllers.HomepageControllerSystem.Web.Mvc.ResultExecutingContextN/A)
  System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(N/AN/AN/AN/A)
  System.Web.Mvc.Async.AsyncControllerActionInvoker+<>c__DisplayClass25.<BeginInvokeAction>b__22(System.Web.Mvc.Async.AsyncControllerActionInvoker+<>c__DisplayClass25N/A)
  System.Web.Mvc.Controller+<>c__DisplayClass1d.<BeginExecuteCore>b__18(N/AN/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.Mvc.Controller.EndExecuteCore(Funda.Web.Mvc.Controllers.HomepageControllerN/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.Mvc.MvcHandler+<>c__DisplayClass8.<BeginProcessRequest>b__3(System.Web.Mvc.MvcHandler+<>c__DisplayClass8N/A)
  System.Web.Mvc.Async.AsyncResultWrapper+<>c__DisplayClass4.<MakeVoidDelegate>b__3(N/AN/A)
  System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute(N/A)
  System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute(N/A)
  System.Web.HttpApplication.ExecuteStep(ASP.global_asaxN/ASystem.Boolean&)
  System.Web.HttpApplication.ExecuteStep(N/AN/AN/A)
  System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Web.HttpApplication+PipelineStepManagerN/A)
  System.Web.HttpApplication.BeginProcessRequestNotification(N/AN/AN/A)
  System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.HttpRuntimeSystem.Web.Hosting.IIS7WorkerRequestSystem.Web.HttpContext)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(N/ASystem.IntPtrN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(N/AN/AN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(N/AN/AN/AN/A)
  System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(N/AN/AN/AN/A)


OS Thread Id:25392
  System.LocalDataStoreMgr.GetNamedDataSlot(System.LocalDataStoreMgrN/A)
  Funda.App.Caching.CacheManager.GetFromCache(Funda.App.Caching.CacheManagerSystem.StringSystem.Func`1<Funda.Common.ServiceLayer.KoppelenEngineService.KlantMijnMakelaarKoppeling>)
  Funda.Web.Mvc.Mappers.Shared.MijnMakelaarMapper.GetMijnMakelaarKoppeling(N/AN/A)
  Funda.Web.Mvc.Mappers.SharedViewModelMapper.MapToLoginViewModel(N/AN/AN/AN/AN/AN/A)
  Funda.Web.Mvc.Attributes.DataForLoginAttribute.OnActionExecuted(N/AN/A)
  ...

I think I understand what Thread Local Storage is, but I don't understand why this call is apparently made from these places. We do not explicitly call Thread.GetNamedDataSlot anywhere. Neither does the BCL code in the methods indicated by these logs (if I may trust ILSpy).

Why is this method called so often? What should I do to prevent this situation (looks like a locking hotspot to me)?


Update

The GetFromCache method(s) can be seen below. The _instrumentation field is static. The implementation of that class, that does involve thread-aware code is also included.

public T GetFromCache<T>(string key, Func<T> fetchAction, bool stampedeProtection, Func<T, Boolean> needsStoring)
{
    // argh?
    key = AddCacheVersionNumberToKey(key);

    long startTime = 0;
    long endTime = 0;
    int timesSlept = 0;
    if (_usingCounters)
    {
        NativeMethods.QueryPerformanceCounter(ref startTime);
    }
    _log.Debug("GetFromCache: [" + _durationGroup + "] " + key);

    object obj = null;
    while (obj == null)
    {
        obj = _store.Get(key);
        if(obj is NotImplementedException)
        {
            // this is a nasty case where the store is not able to deserialize without knowing the type
            obj = _store.Get<T>(key);
        }
        if (obj is NullValue)
        {
            return default(T);
        }
        if (CacheDisabledFromUrl(key) || obj is String && string.IsNullOrEmpty(obj.ToString()))
        {
            obj = null;
        }
        if (obj == null)
        {
            // Niet gevonden
            if (timesSlept > Settings.Default.StampedeMaxSleepCycles)
            {
                _log.WarnFormat("Waiting for {0} x {1} ms for a locked cache key. Some other thread is taking very long to fill {2}. We will try it ourselves.", Settings.Default.StampedeMaxSleepCycles, Settings.Default.StampedeSleepTime, key);

                stampedeProtection = false;
            }
            if (stampedeProtection)
            {
                // special case: we want to make sure that only one thread does the fetch after the miss.
                if (_store.AcquireLock(key))
                {
                    if (_usingCounters)
                    {
                        // log a miss only when we acquire the lock: other cases are just a slow hit
                        NativeMethods.QueryPerformanceCounter(ref endTime);
                        _instrumentation.RegisterMiss(_durationGroup, endTime - startTime, key);
                        startTime = endTime;
                    }

                    try
                    {
                        // We have to do the work
                        obj = fetchAction.Invoke();
                        if (_usingCounters)
                        {
                            NativeMethods.QueryPerformanceCounter(ref endTime);
                            _instrumentation.RegisterFetch(_durationGroup, obj, endTime - startTime, key);
                        }
                        if (obj == null)
                        {
                            _store.Store(key, new NullValue());

                            return default(T);
                        }
                        else if (needsStoring((T)obj))
                        {

                            if (_usingCounters)
                            {
                                NativeMethods.QueryPerformanceCounter(ref startTime);
                            }
                            _store.Store<T>(key, (T)obj);
                            if (_usingCounters)
                            {
                                NativeMethods.QueryPerformanceCounter(ref endTime);
                                _instrumentation.RegisterStore(_durationGroup, obj, endTime - startTime, key);
                            }
                        }
                    }
                    finally
                    {
                        _store.ReleaseLock(key);
                    }
                }
                else
                {
                    // Wait and try again
                    // after 500 ms, hopefully, another thread will have filled the cache
                    Thread.Sleep(500);
                    timesSlept++;
                }
            }
            else
            {
                // Standard flow for miss: fetch and store
                if (_usingCounters)
                {
                    // log a miss
                    NativeMethods.QueryPerformanceCounter(ref endTime);
                    _instrumentation.RegisterMiss(_durationGroup, endTime - startTime, key);
                    startTime = endTime;
                }
                obj = fetchAction.Invoke();
                if (_usingCounters)
                {
                    // log a fetch
                    NativeMethods.QueryPerformanceCounter(ref endTime);
                    _instrumentation.RegisterFetch(_durationGroup, obj, endTime - startTime, key);
                }
                if (obj == null)
                {
                    _store.Store(key, new NullValue());

                    return default(T);
                }
                if (needsStoring((T)obj))
                {
                    if (_usingCounters) NativeMethods.QueryPerformanceCounter(ref startTime);
                    _store.Store<T>(key, (T)obj);
                    if (_usingCounters)
                    {
                        NativeMethods.QueryPerformanceCounter(ref endTime);
                        _instrumentation.RegisterStore(_durationGroup, obj, endTime - startTime, key);
                    }
                }
            }
        }
        else
        {
            // Get is (uiteindelijk) gelukt. We loggen een Hit
            if (_usingCounters)
            {
                NativeMethods.QueryPerformanceCounter(ref endTime);
                _instrumentation.RegisterHit(_durationGroup, obj, endTime - startTime, key);
            }

            if (HttpContext.Current != null && HttpContext.Current.Request.Url.Query.Contains("queryinfo") && QueryTraceHttpContextAppender.Current != null)
            {
                string storeName = _store.GetType().Name.Replace("Store", "");
                QueryTraceHttpContextAppender.Current.AppendDirect(String.Format("{0}: [Key] {1}", storeName, key));
            }
        }
    }
    return (T)obj;
}

More extensive code snippet here.


Conclusions

It turned out that the strange call was indeed caused by the New Relic Agent. The methods in case are all instrumented methods. However, with New Relic disabled, the performance problem did not go away. The stacks were more informative though. So question answered. @jessehouwing, if you reformulate your remark as an answer, I'd be happy to accept.

like image 592
Teun D Avatar asked Jan 16 '14 10:01

Teun D


1 Answers

I found this explanation

"Threads use a local store memory mechanism to store thread-specific data. The common language runtime allocates a multi-slot data store array to each process when it is created. The thread can allocate a data slot in the data store, store and retrieve a data value in the slot, and free the slot for reuse after the thread expires. Data slots are unique per thread. No other thread (not even a child thread) can get that data.

If the named slot does not exist, a new slot is allocated. Named data slots are public and can be manipulated by anyone. "

The source is :http://msdn.microsoft.com/en-us/library/system.threading.thread.getnameddataslot%28v=vs.110%29.aspx

in this article explain that is possible to rewrite this behavior

http://msdn.microsoft.com/en-us/library/6sby1byh%28v=vs.110%29.aspx

the problem i think is that .net are reusing the same name for save the slot and this cause the bad performance.

is posible than one solution is to clean the runtime callable wrappers.

i found this:

http://msdn.microsoft.com/en-us/library/system.threading.thread.disablecomobjecteagercleanup%28v=vs.100%29.aspx

like image 81
Fermin Pitol Avatar answered Nov 19 '22 17:11

Fermin Pitol