Sitecore Custom LinkProvider hangs Sitecore Indexing

This blog is to discuss an indexing hang issue I found recently while I was working on a Commerce Connect Synchronization implementation. In my last blog post I mentioned, how a custom synchronization provider can be used to re-index items after importing the items from external commerce system. This was working fine but, recently I found that, as I run the synchronization, the synchronization status progress box spins for ever. To see what the progress box is doing, I started Fiddler and found that it’s checking the status of the job every 1000 milliseconds and the job is on hung state.

Not sure what’s going on, I took a memory dump of the worker process. I opened the hang dump in Windbg and started looking into clr stack of all threads running in the process. There are two stacks that got my attention. The one below showed that the custom link provider was called by index crawler and the thread was going to the wait state, waiting to acquire the lock it released.

 

        Child SP               IP Call Site
00000082f9f6d448 00007ffb0fe41c2a [GCFrame: 00000082f9f6d448]
00000082f9f6d518 00007ffb0fe41c2a [HelperMethodFrame_1OBJ: 00000082f9f6d518] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
00000082f9f6d630 00007ffb024aab2c System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken)
00000082f9f6d6f0 00007ffb024a366b System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken)
00000082f9f6d780 00007ffb02ce080a System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken)
00000082f9f6d880 00007ffb02ced556 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].GetResultCore(Boolean)
00000082f9f6d8c0 00007ffaa73f5b99 Src.Smartworks.ApiClient.Public.Catalog.CatalogsClient.GetCatalogTreeForCatalog(Int32)
00000082f9f6d930 00007ffaa73f59f1 Src.Smartworks.Web.Services.EcommerceLinksService.GetExternalCatalog(Int32)
00000082f9f6d9c0 00007ffaa73f591f Src.Smartworks.Web.Services.EcommerceLinksService.GetExternalCatalog(Sitecore.Data.Items.Item)
00000082f9f6da30 00007ffaa73f57e5 Src.Smartworks.Web.Services.EcommerceLinksService.GetCatalogUrl(Sitecore.Data.Items.Item)
00000082f9f6da80 00007ffaa73d2be3 Src.Smartworks.Web.Services.EcommerceLinksProvider.GetCatalogUrl(Sitecore.Data.Items.Item)
00000082f9f6db10 00007ffaa6f7659a Src.Smartworks.Web.Services.EcommerceLinksProvider.GetItemUrl(Sitecore.Data.Items.Item, Sitecore.Links.UrlOptions)
00000082f9f6dbc0 00007ffaa733b4b3 Sitecore.ContentSearch.ComputedFields.UrlLink.ComputeFieldValue(Sitecore.ContentSearch.IIndexable)
00000082f9f6dc00 00007ffaa733890f Sitecore.ContentSearch.LuceneProvider.LuceneDocumentBuilder.AddComputedIndexFields()
00000082f9f6dce0 00007ffaa7332804 Sitecore.ContentSearch.LuceneProvider.LuceneIndexOperations.GetIndexData(Sitecore.ContentSearch.IIndexable, Sitecore.ContentSearch.IProviderUpdateContext)
00000082f9f6dd50 00007ffaa73323c4 Sitecore.ContentSearch.LuceneProvider.LuceneIndexOperations.BuildDataToIndex(Sitecore.ContentSearch.IProviderUpdateContext, Sitecore.ContentSearch.IIndexable)
00000082f9f6dda0 00007ffaa7332090 Sitecore.ContentSearch.LuceneProvider.LuceneIndexOperations.Update(Sitecore.ContentSearch.IIndexable, Sitecore.ContentSearch.IProviderUpdateContext, Sitecore.ContentSearch.ProviderIndexConfiguration)
00000082f9f6ddf0 00007ffaa7331a9b Sitecore.ContentSearch.SitecoreItemCrawler.DoUpdate(Sitecore.ContentSearch.IProviderUpdateContext, Sitecore.ContentSearch.SitecoreIndexableItem)
00000082f9f6de90 00007ffaa7330ef6 Sitecore.ContentSearch.HierarchicalDataCrawler`1[[System.__Canon, mscorlib]].CrawlItem(System.Tuple`3<System.__Canon,Sitecore.ContentSearch.IProviderUpdateContext,CrawlState`1<System.__Canon,System.__Canon>>)
00000082f9f6df80 00007ffb024a30ee System.Threading.Tasks.Task.Execute()
00000082f9f6dff0 00007ffb02408355 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
00000082f9f6e150 00007ffb024080c9 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
00000082f9f6e180 00007ffb024a33c5 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
00000082f9f6e260 00007ffb024a2a65 System.Threading.Tasks.Task.ExecuteEntry(Boolean)
00000082f9f6e2a0 00007ffaa73d23b1 Sitecore.ContentSearch.LimitedConcurrencyLevelTaskScheduler.<NotifyThreadPoolOfPendingWork>b__3(System.Object)
00000082f9f6e310 00007ffb0248b193 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
00000082f9f6e360 00007ffb0248a22a System.Threading.ThreadPoolWorkQueue.Dispatch()
00000082f9f6e8b8 00007ffb03db0453 [DebuggerU2MCatchHandlerFrame: 00000082f9f6e8b8]
00000082f9f6ea58 00007ffb03db0453 [ContextTransitionFrame: 00000082f9f6ea58]
00000082f9f6ec78 00007ffb03db0453 [DebuggerU2MCatchHandlerFrame: 00000082f9f6ec78]

 

The second thread that got my attention was the one below. This thread was started to refresh the index by the synchronization provider. This thread is going into sleep and holding the lock released by the above thread.

        Child SP               IP Call Site
00000082f723d358 00007ffb0fe419ba [HelperMethodFrame: 00000082f723d358] System.Threading.Thread.SleepInternal(Int32)
00000082f723d450 00007ffb0248f399 System.Threading.Thread.Sleep(Int32)
00000082f723d480 00007ffaa7330837 *** ERROR: Module load completed but symbols could not be loaded for Sitecore.ContentSearch.dll
Sitecore.ContentSearch.HierarchicalDataCrawler`1[[System.__Canon, mscorlib]].UpdateHierarchicalRecursive(Sitecore.ContentSearch.IProviderUpdateContext, System.__Canon, System.Threading.CancellationToken)
00000082f723d540 00007ffaa733011d Sitecore.ContentSearch.HierarchicalDataCrawler`1[[System.__Canon, mscorlib]].RefreshFromRoot(Sitecore.ContentSearch.IProviderUpdateContext, System.__Canon, Sitecore.ContentSearch.IndexingOptions, System.Threading.CancellationToken)
00000082f723d5c0 00007ffaa7304feb *** ERROR: Module load completed but symbols could not be loaded for Sitecore.ContentSearch.LuceneProvider.dll
Sitecore.ContentSearch.LuceneProvider.LuceneIndex.PerformRefresh(Sitecore.ContentSearch.IIndexable, Sitecore.ContentSearch.IndexingOptions, System.Threading.CancellationToken)
00000082f723d660 00007ffaa7304d05 Sitecore.ContentSearch.LuceneProvider.LuceneIndex.Refresh(Sitecore.ContentSearch.IIndexable)
00000082f723d690 00007ffaa732d6b8 *** WARNING: Unable to verify checksum for Src.Smartworks.Sitecore.Connector.dll
*** ERROR: Module load completed but symbols could not be loaded for Src.Smartworks.Sitecore.Connector.dll
Src.Smartworks.Sitecore.Connector.Providers.SmartworksProductSynchronizationProvider.RefreshIndexes()
00000082f723d810 00007ffaa73074a3 Src.Smartworks.Sitecore.Connector.Providers.SmartworksProductSynchronizationProvider.SynchronizeArtifacts(Sitecore.Commerce.Services.Products.SynchronizationRequest)
00000082f723dc38 00007ffb03db0453 [DebuggerU2MCatchHandlerFrame: 00000082f723dc38] 
00000082f723df38 00007ffb03db0453 [HelperMethodFrame_PROTECTOBJ: 00000082f723df38] System.RuntimeMethodHandle.InvokeMethod(System.Object, System.Object[], System.Signature, Boolean)
00000082f723e0b0 00007ffb023dc4c5 System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(System.Object, System.Object[], System.Object[])
00000082f723e120 00007ffb02490603 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
00000082f723e1a0 00007ffb0248f413 System.Reflection.MethodBase.Invoke(System.Object, System.Object[])
00000082f723e1e0 00007ffaa72f918b DynamicClass.(System.Object, System.Object[])
00000082f723e220 00007ffaa47f546d Sitecore.Pipelines.CorePipeline.Run(Sitecore.Pipelines.PipelineArgs)
00000082f723e2b0 00007ffaa7303515 Sitecore.Jobs.Job.ThreadEntry(System.Object)
00000082f723e340 00007ffaa47dd385 Sitecore.Threading.ManagedThreadPool.ProcessQueuedItems()
00000082f723e3b0 00007ffb02408355 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
00000082f723e510 00007ffb024080c9 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
00000082f723e540 00007ffb024080a7 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
00000082f723e590 00007ffb0248da71 System.Threading.ThreadHelper.ThreadStart()
00000082f723e898 00007ffb03db0453 [GCFrame: 00000082f723e898] 
00000082f723ebe8 00007ffb03db0453 [DebuggerU2MCatchHandlerFrame: 00000082f723ebe8] 
00000082f723ed88 00007ffb03db0453 [ContextTransitionFrame: 00000082f723ed88] 
00000082f723efa8 00007ffb03db0453 [DebuggerU2MCatchHandlerFrame: 00000082f723efa8] 

 

After after looking into the local variables of the HierarchicalDataCrawler.UpdateHierarchicalRecursive method in the debugger, it seems, the following highlighted code is going into infinite loop.

      Assert.ArgumentNotNull((object) context, "context");
      Assert.ArgumentNotNull((object) indexable, "indexable");
      HierarchicalDataCrawler<T>.CrawlState<T> crawlState = new HierarchicalDataCrawler<T>.CrawlState<T>(this.index, cancellationToken)
      {
        ItemAction = new Action<IProviderUpdateContext, T>(((Crawler<T>) this).DoUpdate),
        ItemActionErrorMessage = "Crawler : UpdateRecursive UpdateItem failed - {0}"
      };
      try
      {
        this.currentCrawlOperations[crawlState.Id] = crawlState;
        lock (crawlState)
          ++crawlState.PendingCrawlCount;
        this.CrawlItem(new Tuple<T, IProviderUpdateContext, HierarchicalDataCrawler<T>.CrawlState<T>>(indexable, context, crawlState));
        while ((crawlState.PendingCrawlCount > 0L || crawlState.CurrentTasks.Count > 0) && (!crawlState.IsCancelled && !crawlState.CancellationToken.IsCancellationRequested))
          Thread.Sleep(50);
      }
      finally
      {
        this.currentCrawlOperations.Remove(crawlState.Id);
      }

 

If I disable the custom link provider, indexing works fine again. I haven’t found any reference to this issue in internet. I would like to know if anyone saw this issue and if there is a solution for this. The version of Sitecore is 7.5 rev.141003.

Advertisements

About Himadri Chakrabarti

I am a software developer architect and a Sitecore MVP. My professional interest is everything and anything related to Software Architecture, .NET, Sitecore, Node.js, NoSQL etc. Outside of my profession, I am a hobbyist photographer. Link to my photography site http://himadriphotography.com/
This entry was posted in Commerce Connect, Debugging, Sitecore and tagged , . Bookmark the permalink.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s