JsPoolExhaustedException #251

Closed
huan086 opened this Issue Apr 9, 2016 · 15 comments

Projects

None yet

3 participants

@huan086
huan086 commented Apr 9, 2016

I'm running into JsPoolExhaustedException after running React.NET continuously for 5 days. I suspect the JavaScript engine is not being returned into the pool. How can I find where the leak is?

@Daniel15
Member
Daniel15 commented Apr 9, 2016

Are you logging exceptions that occur in the site? Can you see if there's any exceptions relating to the JavaScript engine?

@huan086
huan086 commented Apr 9, 2016

The exception don't seem meaningful to me. JsPoolExhaustedException only occurs after days of running

JSPool.Exceptions.JsPoolExhaustedException: Could not acquire JavaScript engine within 00:00:05
   at JSPool.JsPool.GetEngine(Nullable`1 timeout)
   at React.JavaScriptEngineFactory.GetEngine()
   at System.Lazy`1.CreateValue()
   at System.Lazy`1.LazyInitValue()
   at React.ReactEnvironment.get_Engine()
   at React.ReactEnvironment.EnsureUserScriptsLoaded()
   at React.ReactEnvironment.CreateComponent[T](String componentName, T props, String containerId)
   at React.Web.Mvc.HtmlHelperExtensions.React[T](HtmlHelper htmlHelper, String componentName, T props, String htmlTag, String containerId, Boolean clientOnly, Boolean serverOnly, String containerClass)
   at MyCode.Views.Account.SignIn.Execute() in D:\MyProject\Views\Account\SignIn.cshtml:line 13
   at System.Web.WebPages.WebPageBase.ExecutePageHierarchy()
   at System.Web.Mvc.WebViewPage.ExecutePageHierarchy()
   at System.Web.WebPages.StartPage.ExecutePageHierarchy()
   at System.Web.WebPages.WebPageBase.ExecutePageHierarchy(WebPageContext pageContext, TextWriter writer, WebPageRenderingBase startPage)
   at System.Web.Mvc.ViewResultBase.ExecuteResult(ControllerContext context)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultFilterRecursive(IList`1 filters, Int32 filterIndex, ResultExecutingContext preContext, ControllerContext controllerContext, ActionResult actionResult)
   at System.Web.Mvc.ControllerActionInvoker.InvokeActionResultWithFilters(ControllerContext controllerContext, IList`1 filters, ActionResult actionResult)
   at System.Web.Mvc.Async.AsyncControllerActionInvoker.<>c__DisplayClass21.<BeginInvokeAction>b__1e(IAsyncResult asyncResult)
   at System.Web.Mvc.Controller.<BeginExecuteCore>b__1d(IAsyncResult asyncResult, ExecuteCoreState innerState)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.Controller.EndExecuteCore(IAsyncResult asyncResult)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.Mvc.MvcHandler.<BeginProcessRequest>b__5(IAsyncResult asyncResult, ProcessRequestState innerState)
   at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncVoid`1.CallEndDelegate(IAsyncResult asyncResult)
   at System.Web.HttpApplication.CallHandlerExecutionStep.OnAsyncHandlerCompletion(IAsyncResult ar)
@huan086
huan086 commented Apr 9, 2016

Looking throw React.NET code, I've found a "bad idea" so far

In ReactEnvironment class, _engineFromPool = new Lazy<IJsEngine>(() => _engineFactory.GetEngine()). The Lazy class caches the result of the first invocation. That is, if the first invocation causes an exception, ALL subsequent calls will return an exception.

I'm using my own implementation for keeping Singleton, which is way simpler than Lazy's implementation as it does not need to capture the exception and rethrow

namespace MyCompany
{
    using System;

    /// <summary>
    ///   As opposed to the <see cref="T:System.Lazy&lt;T&gt;" /> class that stores exception that is thrown during construction,
    ///   this class only stores successfully constructed objects.
    ///   <see href="https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Microsoft_.NET_.28Visual_Basic.2C_C.23.29">Double checked locking</see>
    /// </summary>
    /// <typeparam name="T">The type of the value.</typeparam>
    public class Singleton<T>
        where T : class
    {
        private readonly object syncLock = new object();

        private readonly Func<T> valueFactory;

        private T instance;

        public Singleton(Func<T> valueFactory)
        {
            if (valueFactory == null)
            {
                throw new ArgumentNullException("valueFactory");
            }

            this.valueFactory = valueFactory;
        }

        public T Value
        {
            get
            {
                if (this.instance == null)
                {
                    lock (this.syncLock)
                    {
                        if (this.instance == null)
                        {
                            this.instance = this.valueFactory();
                        }
                    }
                }

                return this.instance;
            }
        }
    }
}

@huan086
huan086 commented Apr 9, 2016

Found an issue

JavaScriptEngineFactory is registered as singleton. JavaScriptEngineFactory has JsPool. Thus, JsPool is singleton. JsPool has Dictionary _metadata, which is not thread-safe. Access to _metadata in CreateEngine, TakeEngine, ReturnEngineToPool and DisposeEngine do not use any synchronization, thus potentially modifying _metadata from different threads and corrupting it.

Switching to ConcurrentDictionary should solve the issue. Additionally, this._engineCount should be replaced by _metadata.Count in order to get a consistent count to prevent race condition.

Race condition: consider where engine is released and requested from different thread, one thread releases, the other request, but fails at this.EngineCount < this._config.MaxEngines due to this.EngineCount not being decrement yet.

@huan086 huan086 referenced this issue in Daniel15/JSPool Apr 9, 2016
Closed

Corcurrency problem in JsPool _metadata #13

@Daniel15
Member
Daniel15 commented Apr 9, 2016

Thanks for the information! I switched _metadata to a ConcurrentDictionary in JSPool 0.3.2, which should fix this issue. Let me know if you still encounter it.

Race condition: consider where engine is released and requested from different thread, one thread releases, the other request, but fails at this.EngineCount < this._config.MaxEngines due to this.EngineCount not being decrement yet.

I considered this, but creation of a single extra JavaScript engine wasn't too much of a concern.

@Daniel15 Daniel15 closed this Apr 9, 2016
@dustinsoftware
Contributor

Thanks for pushing a fix, just ran into this bug on production. 👍

@dustinsoftware
Contributor

Edit: Unfortunately, about 6 hours after deploying the fix, we ran into the same exception being thrown (Could not acquire JavaScript engine within 00:00:05). Going to do some more investigating...

@Daniel15
Member

You can turn off pooling (.SetReuseJavaScriptEngines(false) in the config) which will avoid the issue but it'll also be slower, as every request will need to create a brand new JavaScript engines and load all the code all over again. It sounds like JavaScript engines aren't being returned to the pool correctly for some reason, or you're actually exhausting the pool (which can happen if you have more than 25 simultaneous requests, as that's the default config for number of engines). How often are you seeing this error?

You can increase the maximum engine count using SetMaxEngines in the config.

@dustinsoftware
Contributor

After load testing for about an hour on my local machine, I was able to repro the issue. Running an independent load test on JSPool alone using the test suite did not trigger this bug, so I suspicious of this TinyIoC logic that's responsible for returning the current JS engine to the pool after a web request completes. I don't see any evidence of memory corruption in _availableEngines or _metadata. Still investigating.

I'm using MVC 5. These screenshots are from _engineFactory after my local load testing. I ran one web request after the load test to trigger the breakpoint for these screenshots before the engine was claimed.

screen shot 2016-04-14 at 10 30 19 pm

screen shot 2016-04-14 at 10 33 11 pm

@Daniel15
Member

Hmm, interesting. Thanks for looking into it! I wonder if there's cases where EndRequest is not actually called at the end of the request. Could you try explicitly registering the IocPerRequestDisposal module in your Web.config and see if that helps? Something like this should work in the httpModules section:

<add name="IocPerRequestDisposal" type="React.Web.WebInitializer.IocPerRequestDisposal"/>

The other thing you could try is adding an EndRequest event handler in Global.asax.cs and calling HttpContextLifetimeProvider.DisposeAll() there.

Did you see any exceptions? I wonder if some sort of exception would cause the disposal to fail.

@dustinsoftware
Contributor

Ok, I found the problem. Potentially expensive work is being performed in child actions in my project. A JS engine is acquired from the pool when the first Html.React call is hit, but then a call to a child action via Html.Action occurs. In this case, the child action looks up data from a Redis cache, and returns that in a partial view. It looks like the Redis library I'm using causes the current thread to sleep until the I/O completion happens on a different thread, which allows other worker threads to process incoming requests, which is great! However, if our Redis server gets swamped, all of the JS engines get used up by worker threads that are asleep waiting for Redis to respond, and incoming requests try to acquire a new engine, which causes the exhaustion. This could also happen if the child action was waiting asynchronously on an API to respond, e.g. await _client.GetStuffAsync().

It would be awesome if there was a way for Html.React to acquire and free and engine immediately after the component has been rendered, instead of holding on to it for the entire request. The alternative would be to avoid doing anything expensive in a child action, which is doable, but would require refactoring a lot of the views in this project to move that work out of child actions.

What do you think?

@Daniel15
Member

It would be awesome if there was a way for Html.React to acquire and free and engine immediately after the component has been rendered, instead of holding on to it for the entire request.

Hmm, it might be possible, although currently ReactJS.NET assumes that the ReactEnvironment (and thus the JS engine) is scoped to the request, so you'd have to double-check that everything still works as expected if that assumption no longer holds true. I don't have any plans on changing this, although I'm happy to accept pull requests :)

@huan086
huan086 commented Apr 25, 2016

I'm running into this problem again...

@huan086
huan086 commented Apr 26, 2016

Investigating the issue again. According to http://weblog.west-wind.com/posts/2004/Jun/15/ResponseEnd-bites-back-at-HttpApplication-events, EndRequest won't get called if I do Server.Transfer. In my code, there is HttpContext.Current.Server.TransferRequest. However, I couldn't find any leaks after the call as JsPool.AvailableEngineCount stays at 25.

My ReactConfig is

            ReactSiteConfiguration.Configuration
                .SetLoadReact(false)
                .SetLoadBabel(false)
                .SetAllowMsieEngine(false)
                .AddScriptWithoutTransform("~/Scripts/react-with-addons.min.js")
                .AddScriptWithoutTransform("~/Scripts/react-dom.min.js")
                .AddScriptWithoutTransform("~/Scripts/react-dom-server.min.js")
                .AddScriptWithoutTransform("~/Scripts/moment-with-locales.min.js")
                .AddScriptWithoutTransform("~/Scripts/server/Compatibility.js")
                .AddScriptWithoutTransform("~/js/server/components.min.js");

Any idea where else I should look?

@dustinsoftware
Contributor

@huan086 I pushed a fix in #270. I'll be doing some more thorough testing later but it should resolve this problem for you, as it no longer relies on the DI container firing an event to return the JS engine to the pool.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment