From 9d27e577e0f158e44cd7bb4b9fbf4915eb46183b Mon Sep 17 00:00:00 2001 From: Sebastien Ros Date: Fri, 11 Mar 2016 17:19:25 -0800 Subject: [PATCH] Improving output cache performance - Preventing multiple requests from requesting the same cache item concurrently - Using TaskCompletionSource to synchronize workers instead of locks --- .../Filters/OutputCacheFilter.cs | 327 ++++++++++-------- .../Orchard.OutputCache.csproj | 2 + .../Services/CacheService.cs | 2 +- .../Services/DefaultCacheStorageProvider.cs | 15 + .../Services/IOutputCacheFilterState.cs | 19 + .../Services/OutputCacheFilterState.cs | 16 + 6 files changed, 240 insertions(+), 141 deletions(-) create mode 100644 src/Orchard.Web/Modules/Orchard.OutputCache/Services/IOutputCacheFilterState.cs create mode 100644 src/Orchard.Web/Modules/Orchard.OutputCache/Services/OutputCacheFilterState.cs diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Filters/OutputCacheFilter.cs b/src/Orchard.Web/Modules/Orchard.OutputCache/Filters/OutputCacheFilter.cs index 91bded39f..f75aeb669 100644 --- a/src/Orchard.Web/Modules/Orchard.OutputCache/Filters/OutputCacheFilter.cs +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Filters/OutputCacheFilter.cs @@ -5,7 +5,7 @@ using System.Globalization; using System.Linq; using System.Net; using System.Text; -using System.Threading; +using System.Threading.Tasks; using System.Web; using System.Web.Mvc; using System.Web.Routing; @@ -39,10 +39,13 @@ namespace Orchard.OutputCache.Filters { private readonly ICacheService _cacheService; private readonly ISignals _signals; private readonly ShellSettings _shellSettings; + private readonly IOutputCacheFilterState _state; + private bool _isDisposed = false; public ILogger Logger { get; set; } + public OutputCacheFilter( ICacheManager cacheManager, IOutputCacheStorageProvider cacheStorageProvider, @@ -53,8 +56,9 @@ namespace Orchard.OutputCache.Filters { IClock clock, ICacheService cacheService, ISignals signals, - ShellSettings shellSettings) { - + ShellSettings shellSettings, + IOutputCacheFilterState state) { + _state = state; _cacheManager = cacheManager; _cacheStorageProvider = cacheStorageProvider; _tagCache = tagCache; @@ -104,7 +108,7 @@ namespace Orchard.OutputCache.Filters { return; // Computing the cache key after we know that the request is cacheable means that we are only performing this calculation on requests that require it - _cacheKey = String.Intern(ComputeCacheKey(filterContext, GetCacheKeyParameters(filterContext))); + _cacheKey = ComputeCacheKey(filterContext, GetCacheKeyParameters(filterContext)); _invariantCacheKey = ComputeCacheKey(filterContext, null); Logger.Debug("Cache key '{0}' was created.", _cacheKey); @@ -117,53 +121,44 @@ namespace Orchard.OutputCache.Filters { if (allowServeFromCache && cacheItem != null) { Logger.Debug("Item '{0}' was found in cache.", _cacheKey); + + if(cacheItem.IsValid(_now)) { + Logger.Debug("Cached item is valid: {0}", _cacheKey); + ServeCachedItem(filterContext, cacheItem); + return; + } + else { + Logger.Debug("Cached item is invalid: {0}", _cacheKey); - // Is the cached item in its grace period? - if (cacheItem.IsInGracePeriod(_now)) { - - // Render the content unless another request is already doing so. - if (Monitor.TryEnter(_cacheKey)) { + // If the cached item is in its grace period + // and there are no current renderer, this request renders the new content + if (cacheItem.IsInGracePeriod(_now) && + !_state.Renderers.ContainsKey(_cacheKey)) { Logger.Debug("Item '{0}' is in grace period and not currently being rendered; rendering item...", _cacheKey); - BeginRenderItem(filterContext); + BeginRenderItem(filterContext, _cacheKey); return; } - } - - // Cached item is not yet in its grace period, or is already being - // rendered by another request; serve it from cache. - Logger.Debug("Serving item '{0}' from cache.", _cacheKey); - ServeCachedItem(filterContext, cacheItem); - return; - } - - // No cached item found, or client doesn't want it; acquire the cache key - // lock to render the item. - Logger.Debug("Item '{0}' was not found in cache or client refuses it. Acquiring cache key lock...", _cacheKey); - if (Monitor.TryEnter(_cacheKey)) { - Logger.Debug("Cache key lock for item '{0}' was acquired.", _cacheKey); - - // Item might now have been rendered and cached by another request; if so serve it from cache. - if (allowServeFromCache) { - cacheItem = GetCacheItem(_cacheKey); - if (cacheItem != null) { - Logger.Debug("Item '{0}' was now found; releasing cache key lock and serving from cache.", _cacheKey); - Monitor.Exit(_cacheKey); + else { + // Cached item not is in its grace period + // or is already being rendered by another request; serve it from cache. + Logger.Debug("Cache item is invalid: {0}", _cacheKey); ServeCachedItem(filterContext, cacheItem); return; } - } + } } // Either we acquired the cache key lock and the item was still not in cache, or // the lock acquisition timed out. In either case render the item. Logger.Debug("Rendering item '{0}'...", _cacheKey); - BeginRenderItem(filterContext); - + BeginRenderItem(filterContext, _cacheKey); } catch { // Remember to release the cache key lock in the event of an exception! Logger.Debug("Exception occurred for item '{0}'; releasing any acquired lock.", _cacheKey); - ReleaseCacheKeyLock(); + + ReleaseWorkers(); + throw; } } @@ -177,97 +172,91 @@ namespace Orchard.OutputCache.Filters { public void OnResultExecuted(ResultExecutedContext filterContext) { - var captureHandlerIsAttached = false; - - try { - - // This filter is not reentrant (multiple executions within the same request are - // not supported) so child actions are ignored completely. - if (filterContext.IsChildAction || !_isCachingRequest) + // This filter is not reentrant (multiple executions within the same request are + // not supported) so child actions are ignored completely. + if (filterContext.IsChildAction || !_isCachingRequest) return; - Logger.Debug("Item '{0}' was rendered.", _cacheKey); + Logger.Debug("Item '{0}' was rendered.", _cacheKey); - - if (!ResponseIsCacheable(filterContext)) { - filterContext.HttpContext.Response.Cache.SetCacheability(HttpCacheability.NoCache); - filterContext.HttpContext.Response.Cache.SetNoStore(); - filterContext.HttpContext.Response.Cache.SetMaxAge(new TimeSpan(0)); - return; + + if (!ResponseIsCacheable(filterContext)) { + filterContext.HttpContext.Response.Cache.SetCacheability(HttpCacheability.NoCache); + filterContext.HttpContext.Response.Cache.SetNoStore(); + filterContext.HttpContext.Response.Cache.SetMaxAge(new TimeSpan(0)); + return; + } + + // Determine duration and grace time. + var cacheDuration = _cacheRouteConfig != null && _cacheRouteConfig.Duration.HasValue ? _cacheRouteConfig.Duration.Value : CacheSettings.DefaultCacheDuration; + var cacheGraceTime = _cacheRouteConfig != null && _cacheRouteConfig.GraceTime.HasValue ? _cacheRouteConfig.GraceTime.Value : CacheSettings.DefaultCacheGraceTime; + + // Include each content item ID as tags for the cache entry. + var contentItemIds = _displayedContentItemHandler.GetDisplayed().Select(x => x.ToString(CultureInfo.InvariantCulture)).ToArray(); + + // Capture the response output using a custom filter stream. + var response = filterContext.HttpContext.Response; + var captureStream = new CaptureStream(response.Filter); + response.Filter = captureStream; + + // Add ETag header for the newly created item + var etag = Guid.NewGuid().ToString("n"); + if (HttpRuntime.UsingIntegratedPipeline) { + if (response.Headers.Get("ETag") == null) { + response.Headers["ETag"] = etag; } + } - // Determine duration and grace time. - var cacheDuration = _cacheRouteConfig != null && _cacheRouteConfig.Duration.HasValue ? _cacheRouteConfig.Duration.Value : CacheSettings.DefaultCacheDuration; - var cacheGraceTime = _cacheRouteConfig != null && _cacheRouteConfig.GraceTime.HasValue ? _cacheRouteConfig.GraceTime.Value : CacheSettings.DefaultCacheGraceTime; + captureStream.Captured += (output) => { + try { + // Since this is a callback any call to injected dependencies can result in an Autofac exception: "Instances + // cannot be resolved and nested lifetimes cannot be created from this LifetimeScope as it has already been disposed." + // To prevent access to the original lifetime scope a new work context scope should be created here and dependencies + // should be resolved from it. - // Include each content item ID as tags for the cache entry. - var contentItemIds = _displayedContentItemHandler.GetDisplayed().Select(x => x.ToString(CultureInfo.InvariantCulture)).ToArray(); + using (var scope = _workContextAccessor.CreateWorkContextScope()) { + var cacheItem = new CacheItem() { + CachedOnUtc = _now, + Duration = cacheDuration, + GraceTime = cacheGraceTime, + Output = output, + ContentType = response.ContentType, + QueryString = filterContext.HttpContext.Request.Url.Query, + CacheKey = _cacheKey, + InvariantCacheKey = _invariantCacheKey, + Url = filterContext.HttpContext.Request.Url.AbsolutePath, + Tenant = scope.Resolve().Name, + StatusCode = response.StatusCode, + Tags = new[] { _invariantCacheKey }.Union(contentItemIds).ToArray(), + ETag = etag + }; - // Capture the response output using a custom filter stream. - var response = filterContext.HttpContext.Response; - var captureStream = new CaptureStream(response.Filter); - response.Filter = captureStream; + // Notifying any awaiting thread that the content is ready + // for this page + TaskCompletionSource tcs; + if (_state.Renderers.TryRemove(_cacheKey, out tcs)) { + Logger.Debug("Page rendered, notifying awaiters: {0}", _cacheKey); + tcs.SetResult(cacheItem); + } - // Add ETag header for the newly created item - var etag = Guid.NewGuid().ToString("n"); - if (HttpRuntime.UsingIntegratedPipeline) { - if (response.Headers.Get("ETag") == null) { - response.Headers["ETag"] = etag; - } - } + // Write the rendered item to the cache. + var cacheStorageProvider = scope.Resolve(); + cacheStorageProvider.Set(_cacheKey, cacheItem); - captureStream.Captured += (output) => { - try { - // Since this is a callback any call to injected dependencies can result in an Autofac exception: "Instances - // cannot be resolved and nested lifetimes cannot be created from this LifetimeScope as it has already been disposed." - // To prevent access to the original lifetime scope a new work context scope should be created here and dependencies - // should be resolved from it. + Logger.Debug("Item '{0}' was written to cache.", _cacheKey); - using (var scope = _workContextAccessor.CreateWorkContextScope()) { - var cacheItem = new CacheItem() { - CachedOnUtc = _now, - Duration = cacheDuration, - GraceTime = cacheGraceTime, - Output = output, - ContentType = response.ContentType, - QueryString = filterContext.HttpContext.Request.Url.Query, - CacheKey = _cacheKey, - InvariantCacheKey = _invariantCacheKey, - Url = filterContext.HttpContext.Request.Url.AbsolutePath, - Tenant = scope.Resolve().Name, - StatusCode = response.StatusCode, - Tags = new[] { _invariantCacheKey }.Union(contentItemIds).ToArray(), - ETag = etag - }; - - // Write the rendered item to the cache. - var cacheStorageProvider = scope.Resolve(); - cacheStorageProvider.Set(_cacheKey, cacheItem); - - Logger.Debug("Item '{0}' was written to cache.", _cacheKey); - - // Also add the item tags to the tag cache. - var tagCache = scope.Resolve(); - foreach (var tag in cacheItem.Tags) { - tagCache.Tag(tag, _cacheKey); - } + // Also add the item tags to the tag cache. + var tagCache = scope.Resolve(); + foreach (var tag in cacheItem.Tags) { + tagCache.Tag(tag, _cacheKey); } } - finally { - // Always release the cache key lock when the request ends. - ReleaseCacheKeyLock(); - } - }; - - captureHandlerIsAttached = true; - } - finally { - // If the response filter stream capture handler was attached then we'll trust - // it to release the cache key lock at some point in the future when the stream - // is flushed; otherwise we'll make sure we'll release it here. - if (!captureHandlerIsAttached) - ReleaseCacheKeyLock(); - } + } + catch { + // Release the renderer task in case something happened + ReleaseWorkers(); + } + }; } protected virtual bool RequestIsCacheable(ActionExecutingContext filterContext) { @@ -465,7 +454,7 @@ namespace Orchard.OutputCache.Filters { private CacheSettings CacheSettings { get { - return _cacheSettings ?? (_cacheSettings = _cacheManager.Get(CacheSettings.CacheKey, true, context => { + return _cacheSettings ?? (_cacheSettings = _cacheManager.Get(CacheSettings.CacheKey, context => { context.Monitor(_signals.When(CacheSettings.CacheKey)); return new CacheSettings(_workContext.CurrentSite.As()); })); @@ -508,14 +497,44 @@ namespace Orchard.OutputCache.Filters { ApplyCacheControl(response); } - private void BeginRenderItem(ActionExecutingContext filterContext) { - + private void BeginRenderItem(ActionExecutingContext filterContext, string key) { var response = filterContext.HttpContext.Response; + CacheItem cacheItem = null; - ApplyCacheControl(response); + // Tries to acquire a lock to render an item, or wait for the + // actual render to finish an get the CachedItem directly + TaskCompletionSource tcs; + if (!_state.Renderers.TryGetValue(key, out tcs)) { + Logger.Debug("Acquired processing role: {0}", _cacheKey); - // Remember that we should intercept the rendered response output. - _isCachingRequest = true; + tcs = new TaskCompletionSource(); + + // If the key could not be added it means another thread got there first, + // and in this case they will both try to render the page which is fine. + // The chances are very low however as even at it needs to happen between two + // statements, even at a high RPS it would be uncommon. + _state.Renderers.TryAdd(key, tcs); + } + else { + Logger.Debug("Waiting for processed page: {0}", _cacheKey); + + // We got a task completion source that will have the CacheItem once finished + cacheItem = tcs.Task.Result; + } + + // the cache item can be null if an error occured while rendering + if (cacheItem != null) { + Logger.Debug("Serving result: {0}", _cacheKey); + ServeCachedItem(filterContext, cacheItem); + } + else { + Logger.Debug("Processing page: {0}", _cacheKey); + + ApplyCacheControl(response); + + // Remember that we should intercept the rendered response output. + _isCachingRequest = true; + } } private void ApplyCacheControl(HttpResponseBase response) { @@ -547,15 +566,7 @@ namespace Orchard.OutputCache.Filters { response.Cache.VaryByHeaders[varyRequestHeader] = true; } } - - private void ReleaseCacheKeyLock() { - if (_cacheKey != null && Monitor.IsEntered(_cacheKey)) { - Logger.Debug("Releasing cache key lock for item '{0}'.", _cacheKey); - Monitor.Exit(_cacheKey); - _cacheKey = null; - } - } - + protected virtual bool IsIgnoredUrl(string url, IEnumerable ignoredUrls) { if (ignoredUrls == null || !ignoredUrls.Any()) { return false; @@ -602,15 +613,53 @@ namespace Orchard.OutputCache.Filters { } protected virtual CacheItem GetCacheItem(string key) { - try { - var cacheItem = _cacheStorageProvider.GetCacheItem(key); - return cacheItem; - } - catch (Exception e) { - Logger.Error(e, "An unexpected error occured while reading a cache entry"); - } + TaskCompletionSource tcs; + if (!_state.Cachers.TryGetValue(key, out tcs)) { + tcs = new TaskCompletionSource(); - return null; + // If the key could not be added it means another thread got there first, + // and in this case they will both try to get the cache which is fine. + // The chances are very low however as even at it needs to happen between two + // statements, even at a high RPS it would be uncommon. + _state.Cachers.TryAdd(key, tcs); + + Logger.Debug("Fetching cache item: {0}", _cacheKey); + + try { + var cacheItem = _cacheStorageProvider.GetCacheItem(key); + if (_state.Cachers.TryRemove(key, out tcs)) { + tcs.SetResult(cacheItem); + } + return cacheItem; + } + catch (Exception e) { + Logger.Error(e, "An unexpected error occured while reading a cache entry"); + if (_state.Cachers.TryRemove(key, out tcs)) { + tcs.SetResult(null); + } + return null; + } + } + else { + Logger.Debug("Awaiting cache worker: {0}", _cacheKey); + + // We got a task completion source that will have the CacheItem once finished + return tcs.Task.Result; + } + } + + private void ReleaseWorkers() { + if (_cacheKey != null) { + TaskCompletionSource tcs; + + if (_state.Renderers.TryRemove(_cacheKey, out tcs)) { + tcs.SetResult(null); + } + + if (_state.Cachers.TryRemove(_cacheKey, out tcs)) { + tcs.SetResult(null); + } + } } public void Dispose() { @@ -624,9 +673,7 @@ namespace Orchard.OutputCache.Filters { // Free other state (managed objects). } - if (_cacheKey != null && Monitor.IsEntered(_cacheKey)) { - Monitor.Exit(_cacheKey); - } + ReleaseWorkers(); _isDisposed = true; } diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Orchard.OutputCache.csproj b/src/Orchard.Web/Modules/Orchard.OutputCache/Orchard.OutputCache.csproj index efced387d..b34ba0aa1 100644 --- a/src/Orchard.Web/Modules/Orchard.OutputCache/Orchard.OutputCache.csproj +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Orchard.OutputCache.csproj @@ -115,11 +115,13 @@ + + diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/CacheService.cs b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/CacheService.cs index 75ac547bf..2defa9ae4 100644 --- a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/CacheService.cs +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/CacheService.cs @@ -99,7 +99,7 @@ namespace Orchard.OutputCache.Services { } public IEnumerable GetRouteConfigs() { - return _cacheManager.Get(RouteConfigsCacheKey, true, + return _cacheManager.Get(RouteConfigsCacheKey, ctx => { ctx.Monitor(_signals.When(RouteConfigsCacheKey)); return _repository.Fetch(c => true).Select(c => new CacheRouteConfig { RouteKey = c.RouteKey, Duration = c.Duration, GraceTime = c.GraceTime }).ToReadOnlyCollection(); diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/DefaultCacheStorageProvider.cs b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/DefaultCacheStorageProvider.cs index 23d1b7ed9..d24c0ed0e 100644 --- a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/DefaultCacheStorageProvider.cs +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/DefaultCacheStorageProvider.cs @@ -4,6 +4,7 @@ using System.Collections.Generic; using System.Linq; using Orchard.OutputCache.Models; using Orchard.Environment.Configuration; +using Orchard.Logging; namespace Orchard.OutputCache.Services { public class DefaultCacheStorageProvider : IOutputCacheStorageProvider { @@ -15,7 +16,11 @@ namespace Orchard.OutputCache.Services { _tenantName = shellSettings.Name; } + public ILogger Logger { get; set; } + public void Set(string key, CacheItem cacheItem) { + Logger.Debug("Set {0}", key); + _workContext.HttpContext.Cache.Remove(key); _workContext.HttpContext.Cache.Add( key, @@ -28,10 +33,14 @@ namespace Orchard.OutputCache.Services { } public void Remove(string key) { + Logger.Debug("Remove {0}", key); + _workContext.HttpContext.Cache.Remove(key); } public void RemoveAll() { + Logger.Debug("RemoveAll"); + var items = GetCacheItems(0, 100).ToList(); while (items.Any()) { foreach (var item in items) { @@ -42,10 +51,14 @@ namespace Orchard.OutputCache.Services { } public CacheItem GetCacheItem(string key) { + Logger.Debug("GetCacheItem {0}", key); + return _workContext.HttpContext.Cache.Get(key) as CacheItem; } public IEnumerable GetCacheItems(int skip, int count) { + Logger.Debug("GetCacheItems"); + // the ASP.NET cache can also contain other types of items return _workContext.HttpContext.Cache.AsParallel() .Cast() @@ -57,6 +70,8 @@ namespace Orchard.OutputCache.Services { } public int GetCacheItemsCount() { + Logger.Debug("GetCacheItemsCount"); + return _workContext.HttpContext.Cache.AsParallel() .Cast() .Select(x => x.Value) diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/IOutputCacheFilterState.cs b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/IOutputCacheFilterState.cs new file mode 100644 index 000000000..73c5a9f42 --- /dev/null +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/IOutputCacheFilterState.cs @@ -0,0 +1,19 @@ +using System.Collections.Concurrent; +using System.Threading.Tasks; +using Orchard.OutputCache.Models; + +namespace Orchard.OutputCache.Services { + public interface IOutputCacheFilterState : ISingletonDependency { + + /// + /// Tasks that are currently rendering pages + /// + ConcurrentDictionary> Renderers { get; } + + /// + /// Tasks that are currently retrieving cached items + /// + ConcurrentDictionary> Cachers { get; } + + } +} \ No newline at end of file diff --git a/src/Orchard.Web/Modules/Orchard.OutputCache/Services/OutputCacheFilterState.cs b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/OutputCacheFilterState.cs new file mode 100644 index 000000000..2e361da5d --- /dev/null +++ b/src/Orchard.Web/Modules/Orchard.OutputCache/Services/OutputCacheFilterState.cs @@ -0,0 +1,16 @@ +using System.Collections.Concurrent; +using System.Threading.Tasks; +using Orchard.OutputCache.Models; + +namespace Orchard.OutputCache.Services { + public class OutputCacheFilterState : IOutputCacheFilterState { + public OutputCacheFilterState() { + Cachers = new ConcurrentDictionary>(); + Renderers = new ConcurrentDictionary>(); + } + + public ConcurrentDictionary> Cachers { get; private set; } + + public ConcurrentDictionary> Renderers { get; private set; } + } +} \ No newline at end of file