Login/Register
Why is my code apparently calling LocalDataStoreMgr.GetNamedDataSlot?
Asked Answered
c#asp.netmultithreadingprofilingnewrelic
I

1

9

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.

Inkberry answered 16/1, 2014 at 10:15 Comment(15)
You may not be explicitly making this call - but I wonder if any uses of [ThreadStatic] implicitly end up with a call being made by via the JIT. Is Funda.App.Caching.CacheManager your code, or a 3rd party library? – Potbellied
That is our own code. This class does not use the [ThreadStatic] attribute anywhere, but it does include [DllImport] for the QueryPerformanceCounter win32 API call. No explicit thread locking or anything. – Inkberry
Hmm. I wonder whether you're seeing inlining having an effect - can you post the code of GetFromCache? (I wouldn't expect this to be a "locking hotspot" particularly - one point of thread-local storage is that it doesn't need locking, because it's thread-local...) – Potbellied
The GetFromCache method(s) can be seen here: gist.github.com/Teun/2adf69c1890bc1b067f6 The _instrumentation field is static. The implementation of that class, that does involve thread-aware code is also included. – Inkberry
Do you have any Profilers loaded in the process that could possibly be injecting some code which is causing these calls to LocalDataStoreMgr.GetNamedDataSlot function ??? I would suggest taking memory dumps with Debug Diagnostic tool (microsoft.com/en-us/download/details.aspx?id=40336) and confirm whether the call to "LocalDataStoreMgr.GetNamedDataSlot" is really there in the thread or not. Also looking at the native stack and assembly code of the function from the dump might help as well – Cockaleekie
No .no profilers, except for the stackdump tool itself. Will try the DebugDiag tool. – Inkberry
What version of .NET are you using? What's the value of performance counter ".NET CLR Memory > % Time in GC" when it happens? (Basically, is it an issue with excessive garbage collection?) Does your process consume a lot of memory when this happens (take into account the low limit for 32 bit processes). Does support.microsoft.com/kb/2540745 seem relevant? – Erasion
If you're working for the company I think you're working for, then you're using New Relic (newrelic.com) for online performance measurements. They attach to the process as profiler as far as I can tell. Try temporarily turning off their monitoring agent. – Catherinacatherine
If NewRelic is being used, consider adding the [newrelic] tag to draw in their attention. (Their FAQ mentions they actively follow that tag) – Catherinacatherine
System Center Performance Monitoring or Visual Studio Online Application Insights might also secretly attach a profiler. – Catherinacatherine
I don't think you are in the right direction at all - what happens below the scenes is not the correct way to solve this issue - show us some of your code parts which are involved in creating your form or processing incoming form. problem is likely in there otherwise as you already said others would have found this before you. – Gastrotomy
One way to find possible sources of this type of issue is to load all the assemblies for your application into Reflector.NET or Visual NDepend and then use the Analyze function to find all methods that use or depend upon the LocalDataStoreMgr or the ThreadStatic attribute. You might find something somewhere in the code. – Catherinacatherine
Will try disabling NewRelic temporarily. Sounds like a candidate indeed. – Inkberry
Any update from your side? – Catherinacatherine
Did you read my update in the post? Your tip was spot on. – Inkberry
M
1

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

Medullary answered 25/1, 2014 at 7:11 Comment(1)
Yes, I can see that the C# compiler might be using this call to implement ThreadStatic fields. But I don't use this feature in my code. Check in the Gist I posted. Also, if there was a form of congestion around using ThreadStatic, this would have been found by others before, right? – Inkberry

© 2022 - 2024 — McMap. All rights reserved.