Basic ways of troubleshooting EventQueue challenges

On By kiranpatilsIn Architecture, Caching, EventQueue, Performance, Publishing, Sitecore

Challenge:

In Sitecore 6.3 Sitecore introduced really powerful functionality known as EventQueue. It is really robust piece of functionality. We know value of it. Because we’ve struggled a lot before SC 6.3 to clear partial cache (Do you remember stager module?).  But after 6.3 we haven’t faced major publishing and cache clearing issues! (Touch wood!) Thank you Sitecore champs! What, you are still not using EventQueue? Or using it but not knowing what it is and how it works? I would strongly recommend my earlier post which covers EventQueue basics

Now, as we all know Sitecore is a nice plug-able architecture. So, you can plugin your handlers in publishing or cache clearing pipeline. Or due to one or other reason your publishing slows down or stucks. Or you face performance issues on your front-end servers after publishing. So, if you would like to troubleshoot such challenges then this post is for you.

In Summary, this post will cover following points:

  1. Publishing is slow/stucks [Just a note : If your publishing is slow it can have lot of other reasons. You can read few of the here]
  2. Front-end site’s performance goes down after you publish [Just a note : This can be also reason due to heavy cache clearing. You can read how to troubleshoot CD server’s cache clearing from here]
  3. You have written custom handler in publishing process (e.g. publish:itemProcessing,) and you would like to know how much time it takes?
  4. You use WebDeploy and it is taking how much time during publishing?
  5. If you would like to know how much time Sitecore’s default publish related event handlers take. For example:
    1. user:updated:remote
    2. publish:statusUpdated
    3. item:added:remote
    4. item:versionAdded:remote
    5. item:saved:remote
    6. database:propertychanged
    7. item:created:remote
    8. item:copied:remote
    9. item:sortorderchanged:remote
    10. publish:startPublishing
    11. publish:begin
    12. publish:itemProcessing

Sounds interesting rite? Let’s proceed further:

Solution:

By default Sitecore will not log such detailed information about EventQueue. And it’s obvious to do so. Because it does heavy logging. So, it makes your log file sizes BIG and may affect performance a bit! [Just a note: We’ve used it heavily. But we haven’t faced slow performance due to detailed logging!].

Here are the steps to enable it.

  1.  Go to your server on which you would like to enable event queue logging. Usually following are the candidates where you would be doing it (Depends on your SC architecture):
    1. If your CM (Content Management) and PI (Publish Instance) is on same server then do this on that server only!
    2. If your PI is separate than CM, then do it on PI server only! Because PI will do all the eventque related processing.
    3. If you would like to check how much time EventQueue is taking on CD servers (Remote call is taking how much time?. Then I would recommend it to do on one your CD server only eventhough you got 10 CD servers in your cluster. Provided all 10 connects to same Database.
  2. Take backup of your Web.Config
  3. Open Web.Config
  4. Search for “<events timingLevel=” [without quotes] [Just a note : You can do it at each eventLevl as well. But we are not going in that discussion for now.]
  5. Make it’s value to “high” — e.g. <events timingLevel=”high”> following are the possible values for timingLevel:
    1. none   – No timing information is logged for any of the events (no matter what their local settings are)
    2. low    – Start/end timing is logged for events with handlers. Local settings override.
    3. medium – Start/end timing is logged for all events. Local settings override.
    4. high   – Start/end timing is logged for all events. Also, start/end for each handler is logged. Local settings override.
    5. custom – Only local settings apply. Events without settings are not logged.
  6. Save your web.config!

Now, you are ready to troubleshoot any EventQueue related challenge. Let me share few of interesting log entries you will get from your Sitecore log files after doing settings given above:

Just a note : There are couple of Sitecore log analysis tools available [like Sitecore Log Analyzer and SCLogExplorer] who are really powerful to analyze your log files rapidly. But I believe that when you are learning and exploring something you should start from basics of it. Do it manually, go deep down to it and understand how it works! And all this things you will learn if you do it manually. And once you are through of it by doing manually then you should move to make it automatic or using any tool! Because Basics are always important! So, in this post will use two of my friends only to analyze event log entries and name of them are — Notepad++ and MS-Excel! [Oh, they are your friends too? See, we got common friends! :-)]

Okay, so, you’ve set your EventQueue level as high. Now, let’s see chunk of text from Sitecore log file and how to understand it :

ManagedPoolThread #18 10:57:01 INFO  Job started: Publish to 'web'
ManagedPoolThread #18 10:57:01 INFO  Event started: publish:begin
ManagedPoolThread #18 10:57:01 INFO  Executed: SCBasics.Demo.Publishing.Hooks.PublishBegin.SCWebDeploy.LocalPublish(). Elapsed: 0.213714312852611
ManagedPoolThread #18 10:57:01 INFO  Event ended: publish:begin. Elapsed: 0.605663568973152
ManagedPoolThread #18 10:57:01 INFO  Event started: publish:itemProcessing
ManagedPoolThread #18 10:57:01 INFO  Event started: item:saving
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Tasks.ItemEventHandler.OnItemSaving(). Elapsed: 0.0270984161394814
ManagedPoolThread #18 10:57:01 INFO  Event ended: item:saving. Elapsed: 0.227682568594612
ManagedPoolThread #18 10:57:01 INFO  Event started: item:saved
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Rules.ItemEventHandler.OnItemSaved(). Elapsed: 0.419606402489702
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Links.ItemEventHandler.OnItemSaved(). Elapsed: 31.7626960968503
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Globalization.ItemEventHandler.OnItemSaved(). Elapsed: 0.0324063533214417
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Caching.AccessResultCache.Item_Saved(). Elapsed: 0.0178793673497609
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Caching.RuleCache.OnItemSaved(). Elapsed: 0.094984139045605
ManagedPoolThread #18 10:57:01 INFO  Event ended: item:saved. Elapsed: 33.7308233308982
ManagedPoolThread #18 10:57:01 INFO  Executed: SCBasics.Demo.Publishing.Handlers.UpdateItemStatistics.ItemProcessing(). Elapsed: 51.5104573346612
ManagedPoolThread #18 10:57:01 INFO  Event ended: publish:itemProcessing. Elapsed: 52.1309272547209
ManagedPoolThread #18 10:57:01 INFO  Event started: publish:itemProcessed
ManagedPoolThread #18 10:57:01 INFO  Event ended: publish:itemProcessed. Elapsed: 0.00977777901940051
ManagedPoolThread #18 10:57:01 INFO  Event started: publish:end
ManagedPoolThread #18 10:57:01 INFO  HtmlCacheClearer clearing HTML caches for all sites (1).
ManagedPoolThread #18 10:57:01 INFO  HtmlCacheClearer done.
ManagedPoolThread #18 10:57:01 INFO  Executed: Sitecore.Publishing.HtmlCacheClearer.ClearCache(). Elapsed: 0.210361931474531
ManagedPoolThread #18 10:57:01 INFO  Event ended: publish:end. Elapsed: 0.426869895475542
ManagedPoolThread #18 10:57:01 INFO  Job ended: Publish to 'web' (units processed: 1)

We can understand following bheavior from above log excerpt:

  1. LocalPublish handler took 0.213714312852611 ms
  2. publish:begin event took 0.605663568973152 ms
  3. item:saving event took 0.227682568594612 ms
  4. Sitecore.Caching.AccessResultCache.Item_Saved() event took 0.0178793673497609 ms
  5. item:saved event took 33.7308233308982 ms
  6. Overall publish event took — 0.426869895475542 ms

Now, let’s see how can you plot a graph and analyze the time taken by any event for exampleSitecore.Caching.AccessResultCache.Item_Saved().

  1. Open your Sitecore log file with Notepad++
  2. Search for an event which you would like to delve in to for example “Sitecore.Caching.AccessResultCache.Item_Saved()”
  3. Click on “Find All In Current Document” [If you’ve multiple log files open with Notepad++ you can select other option]
  4. You will see the results in “Find results” window at bottom
  5. Select all of them with full string [e.g. ] and copy it!
  6. Open MS-Excel
  7. When you paste it in excel, excel will suggest you to use “Text Import Wizard” select it
  8. Choose file type as “Delimited”
  9. Click on “Next”
  10. Choose Delimiter as “Space”
  11. Click on “Next”
  12. Choose Column data format as “General”
  13. Click on “Finish”
  14. Delete first four columns
  15. Now, time will be your first column
  16. Delete next four columns
  17. Now, you will have two columns only Time and Elapsed time
  18. Select full data with columns and rows
  19. Go to Insert tab and select chart of your type, for example line
  20. That’s it!

Here’s the sample output:

AccessResultCachep-TimeTaken

Once you do it then it will be easy for you to analyze any issue you are tackling with.  We also used this log entries to troubleshoot issue discussed in last post

Happy Sitecoring! 🙂

2 thoughts on “Basic ways of troubleshooting EventQueue challenges”

  1. Pingback: Sitecore Troubleshooting Path | Sitecore basics!

  2. Pingback: Sitecore EventQueue deadlocks – how to solve them and how to avoid them | Brian Pedersen's Sitecore and .NET Blog

Leave a comment