Template item {ID} not found for item /PATH/PATH

Challenge:

Before couple of weeks back, on our Publishing Instance (PI) we faced a strange issue. Whenever anyone published anything from our CM server via PI Server it was publishing item. But the tokens were as is for example $name. So, the live functionality stopped working.

After checking PI Logs we found following errors:

Template item {24C19083-4E4B-4F18-B4D8-4685B6B74CF3} not found for item /sitecore/content/Home/Test

We saw above error message for the first time. So, as you? After, that we tried to find any exceptions from log file. We found following. But they were after our schedule application pool recycle.

ManagedPoolThread #96 05:07:46 ERROR Failed to load item data
Exception: System.Exception
Message: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Source: Sitecore.Kernel
   at Sitecore.Data.DataProviders.Sql.DataProviderCommand.ExecuteReader()
   at Sitecore.Data.DataProviders.Sql.SqlDataApi.CreateReader(String sql, Object[] parameters)
   at Sitecore.Data.SqlServer.SqlServerDataProvider.LoadItemDefinitions(String condition, Object[] parameters, SafeDictionary`2 prefetchData)

Nested Exception

Exception: System.Data.DataException
Message: Error executing SQL command: SELECT [ItemId], [Order], [Version], [Language], [Name], [Value], [FieldId], [MasterID], [ParentID]
                     FROM (
                        SELECT [Id] as [ItemId], 0 as [Order], 0 as [Version], ” as [Language], [Name], ” as [Value], [TemplateID] as [FieldId], [MasterID], [ParentID]
                        FROM [Items]

                        UNION ALL                         
                        SELECT [ParentId] as [ItemId], 1 as [Order], 0 as [Version], ” as [Language], NULL as [Name], ”, NULL, NULL, [Id]
                        FROM [Items]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order], 0 AS [Version], ” as [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [SharedFields]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order], 0 AS [Version],       [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [UnversionedFields]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order],      [Version],       [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [VersionedFields]
                     ) as temp  WHERE [ItemId] IN (SELECT [ID] FROM [Items] WITH (nolock)  WHERE [ID] = @itemId)
                     ORDER BY [ItemId], [Order] ASC, [Language] DESC, [Version] DESC

Nested Exception

Exception: System.Data.SqlClient.SqlException
Message: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Source: .Net SqlClient Data Provider
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
   at Sitecore.Data.DataProviders.Sql.DataProviderCommand.ExecuteReader()

ManagedPoolThread #96 05:07:47 ERROR Failed to sort items
Exception: System.Exception
Message: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Source: Sitecore.Kernel
   at Sitecore.Data.DataProviders.Sql.DataProviderCommand.ExecuteReader()
   at Sitecore.Data.DataProviders.Sql.SqlDataApi.CreateReader(String sql, Object[] parameters)
   at Sitecore.Data.SqlServer.SqlServerDataProvider.LoadItemDefinitions(String condition, Object[] parameters, SafeDictionary`2 prefetchData)
   at Sitecore.Data.DataProviders.Sql.SqlDataProvider.PrefetchItems(String itemCondition, String fieldCondition, String childCondition, Object[] parameters)
   at Sitecore.Data.DataProviders.Sql.SqlDataProvider.PrefetchItem(ID itemId)
   at Sitecore.Data.DataProviders.Sql.SqlDataProvider.GetPrefetchData(ID itemId)
   at Sitecore.Data.DataProviders.Sql.SqlDataProvider.GetItemDefinition(ID itemId, CallContext context)
   at Sitecore.Data.DataProviders.DataProvider.GetItemDefinition(ID itemID, CallContext context, DataProviderCollection providers)
   at Sitecore.Data.DataSource.GetItemInformation(ID itemID)
   at Sitecore.Data.DataSource.GetItemDefinition(ID itemID)
   at Sitecore.Data.Engines.TemplateEngine.AddSection(ItemDefinition item, Builder template)
   at Sitecore.Data.Engines.TemplateEngine.BuildTemplate(ItemDefinition itemDefinition)
   at Sitecore.Data.Engines.TemplateEngine.AddItemBasedTemplates(TemplateDictionary result)
   at Sitecore.Data.Engines.TemplateEngine.InternalGetTemplates()
   at Sitecore.Data.Engines.TemplateEngine.GetTemplate(ID templateId)
   at Sitecore.Data.Managers.TemplateProvider.GetTemplateField(ID fieldId, Item item)
   at Sitecore.Data.Fields.Field.GetTemplateField()
   at Sitecore.Data.Fields.Field.GetSourceItem()
   at Sitecore.Data.Fields.Field.GetInheritedValue()
   at Sitecore.Data.Fields.Field.GetValue(Boolean allowStandardValue, Boolean allowDefaultValue)
   at Sitecore.Data.Comparers.ComparerFactory.GetComparer(Item item)
   at Sitecore.Data.Managers.ItemProvider.Sort(ItemList items, Item owner)

Nested Exception

Exception: System.Data.DataException
Message: Error executing SQL command: SELECT [ItemId], [Order], [Version], [Language], [Name], [Value], [FieldId], [MasterID], [ParentID]
                     FROM (
                        SELECT [Id] as [ItemId], 0 as [Order], 0 as [Version], ” as [Language], [Name], ” as [Value], [TemplateID] as [FieldId], [MasterID], [ParentID]
                        FROM [Items]

                        UNION ALL                         
                        SELECT [ParentId] as [ItemId], 1 as [Order], 0 as [Version], ” as [Language], NULL as [Name], ”, NULL, NULL, [Id]
                        FROM [Items]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order], 0 AS [Version], ” as [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [SharedFields]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order], 0 AS [Version],       [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [UnversionedFields]

                        UNION ALL
                        SELECT [ItemId], 2 as [Order],      [Version],       [Language], NULL as [Name], [Value], [FieldId], NULL, NULL
                        FROM [VersionedFields]
                     ) as temp  WHERE [ItemId] IN (SELECT [ID] FROM [Items] WITH (nolock)  WHERE [ID] = @itemId)
                     ORDER BY [ItemId], [Order] ASC, [Language] DESC, [Version] DESC

Nested Exception

Exception: System.Data.SqlClient.SqlException
Message: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
Source: .Net SqlClient Data Provider
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning()
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
   at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader()
   at Sitecore.Data.DataProviders.Sql.DataProviderCommand.ExecuteReader()

Totally new exception stacktrace. And we were not sure why they were in the logs? But by looking at StackTrace one thing we were sure, It is something to do with pref-etch cache building. And it had some co-relation with our issue. Which we fixed! Eager to know How? Would like to know the root cause? Would like to know the permanent solution? Easy, Easy we are going to share with you. Just keep reading!

Solution:

It was live issue, and to resolve it we tried following things:

  1. Cleared — items cache, data cache, SQL prefetch cache, and lot of cache for Master/web database etc – No luck yet 😦 [To clear partial cache, We used Caching Manager — http://marketplace.sitecore.net/en/Modules/Caching_Manager.aspx and our in-house tool. Also, this looked promising. But haven’t tried it during our investigation — http://marketplace.sitecore.net/en/Modules/Sitecore_Cache_Admin.aspx]
  2. Cleared full Cache — Using Cache.aspx — But no luck again 😦
  3. We restarted our PI Application — App Pool Recycle and it worked! 🙂

So, after application pool recycle, Everything started working as it should be! All happy! But not we, and not you as well — Correct?. Because to fix any issue and make sure it doesn’t pops up again you should always try to understand root cause. And then try to find a permanent fix for it. Matches with your thinking? See, we got same thinking! 🙂

And guess what we did? Yes, you are right. We raised a Sitecore support case with our config files and log files. At the first instance they replied as follows:

Please try to increase the <setting name=”DefaultSQLTimeout” value=”00:05:00″ /> setting.

Then we checked our configuration settings, and we replied as below:

On our PI Server timeout is 50 Minutes.

<setting name=”DefaultSQLTimeout” value=”00:50:00″/>
<setting name=”DataProviderTimeout” value=”00:50:00″/>

And as we discussed earlier, It doesn’t seems to be a caching issue. Because we cleared full cache already and it didn’t work. And we think that Sitecore is storing Template information somewhere else and not in Caching layers.

And here comes the Sitecore reply, With as always through investigation and explanation:

I’ve investigated the scenario you provided me with and found that indeed SQL exception during templates initialization may break some part of Sitecore items until you recycle the AppPool. I’ve already registered this as a bug for current version of CMS and will inform you when it’s fixed.

Please note that Sitecore is affected by this issue only if exception is thrown during the templates initialization, which happens during the first request to the database items. The possibility of such event is low, but the issue still may happen.

Unfortunately, I don’t see easy ways how to fix the issue, so I cannot provide you with code based workaround. If the issue happened on your solution, you may call the database.Engines.TemplateEngine.Reset() method for each database object (it shouldn’t throw the NRE. If the exception is thrown, please check which property is null and let me know) to reload templates.

The templates subsystem uses its own internal caches in order to increase the performance and more effectively manage entities lifetime. That caches are managed by the TemplateEngine (which belongs to the database) and doesn’t interact with Sitecore Cache subsystem (I mean the Sitecore.Caching.CacheManager class and related ones).
Given that cache clearing doesn’t lead to the templates invalidation. We should explicitly call the database.Engines.TemplateEngine.Reset() method to reset the storage and initiate its entire reloading.

Basically, It has been reported as a BUG and it’s fix is not easy. But as an alternative way you can explicitly Invalidate templates by calling — database.Engines.TemplateEngine.Reset() method!

To be honest, We haven’t seen this error again. And haven’t tried this workaround. But Sitecore support guys reproduced the issue and tried this approach and it works! It worked for you and helped you to fix the live issue? If so, please share your experience with us!

In summary,

  1. Always understand root cause of any issue
  2. Try to understand the challenge and share your findings with Sitecore support guys as much as you can
  3. And Sitecore support guys rock, as always!
  4. Sitecore template has its own internal caches in order to increase the performance and more effectively mange entities lifetime. That cache are managed by the TemplateEngine!

Happy Sitecoring! 🙂

Exception while handling event Sitecore.Publishing.StartPublishingRemoteEvent

Challenge:

Last week, whenever we tried to publish anything in our local development environment, publishing was being shown as “Queued” and it was never publishing an item. When we had a look at log file, we found following error:

Heartbeat 10:25:07 ERROR Exception while handling event Sitecore.Publishing.StartPublishingRemoteEvent
Exception: System.NullReferenceException
Message: Object reference not set to an instance of an object.
Source: Sitecore.Kernel
at Sitecore.Publishing.PublishOptions.GetPublishingTargets()
at Sitecore.Publishing.PublishOptions..ctor(Database sourceDatabase, Database targetDatabase, PublishMode mode, Language
language, DateTime publishDate)
at Sitecore.Publishing.DistributedPublishingManager.DecodeOptions(DistributedPublishOptions options)
at Sitecore.Publishing.DistributedPublishingManager.GetOptions(DistributedPublishOptions[] options)
at Sitecore.Publishing.DistributedPublishingManager.StartPublishing(StartPublishingRemoteEvent event)
at Sitecore.Publishing.RemotePublishingEventHandler.OnStartPublishing(Object sender, EventArgs args)

You are also facing the same error? And struggling to find a solution! (So, as we did last week!). Then this post is for you only!

Solution:

Rather than sharing solution only, we would like to share full troubleshooting way with you.  So, during such challenges, you will be able to know what to check and what not to check during! 🙂 (Because, it takes lot of time to learn, what not to do. And once you learn that you can do anything!)

  1. By looking at error message “System.NullReferenceException ……. Sitecore.Publishing.PublishOptions.GetPublishingTargets()” you may quickly say that — Publishing targets items do not exist in Database. But my dear friend, we verified it for you and they do exist!
  2. When we disabled EventQueue then it worked fine! (Sorry, you are new to EventQueue, no worries — read my earlier post on EventQueue basics) So, something with EventQueue for sure and error message also says so!
  3. Tried same with Plain Sitecore (A good step to follow every time!) – and it was working fine with plain Sitecore. So, for sure something with our application only!
  4. Create a simple page, which published item programmatically and also tried to access publishing targets programmatically, the way it does in publish dialog and it worked!

Tried to had a word with our common friend — Google, and the thing which happens very less happened — Google said I don’t know! 😦 (And that was the motivation behind writing this blog post!)

Then we thought to discus this challenge with our best friends in Sitecore planet — Sitecore support champs!. But as per Sitecore developer’s best practice, It’s always good to have a look at SDN forum (Where all Sitecore friends — discuss their challenges with each other and help them to get out of it! — It’s a great forum) and it turned to be our indeed friend! (Because, a friend in need is a friend in-deed!)

http://sdn.sitecore.net/Forum/ShowPost.aspx?postid=46582

Above link helped us to find a solution!

“Interesting, I wanted to try the security disabler test in isolation and it fixes the problem, so it seems there is something going on with security after all, the context user is default/Anonymous and looking at permissions… In this instance default/Anonymous has not been granted read access to the sitecore Item.

I’ve tested a few other instances and in those read access has been granted on the sitecore Item for default/Anonymous

I don’t know how that happened, I certainly did not edit permissions on the sitecore Item

Thanks for the suggestion Steve “

Basically the reason for this error is access rights only.

So, we had a look in our Database (Master) and found that rights for default\anonymous was removed for /sitecore item. We assigned it and it worked like a charm!

Happy Publishing! 🙂

Transfer tool – Media transfer bug

Challenge:

In a small city, there are two developers cum friends named as Dex and Gabe. They work on Sitecore. And whenever they face any challenge in Sitecore they discuss it internally, try it out and solve it! They are really happy Sitecore developers! (Same as you and I!).

One day they faced a challenge. And this blog post is about how they overcome that challenge.

Disclaimer — All characters in this publication are entirely fictitious and any resemblance to real persons, living or dead, is purely coincidental.

Solution:

Read it from left to right

Transfer-Part1

Transfer-Part2

So, Basically Gabe has suggested to use Transfer tool – http://sdn.sitecore.net/Reference/Archive/SC53%20End%20User/Control%20Panel/Database/Transfer%20Items%20to%20Another%20Database.aspx to Gabe for transferring an item from one DB to another DB without publishing [Worst case scenario!].  And while doing it they found Sitecore Bug in which for media items, it transfers an item. But not a media item itself.

They raised a support case, and Sitecore support guys (Thank you Ivan Sheyenko and Alen Pelin) has provided a solution to them. You also want that solution? You can get it from Sitecore support champs by mentioning them Ticket Reference#’s — #375516 and #376422 [Sitecore.Support.345233.dll]

Just a note : Transfer is not an option of publishing. Because Transfer only copies item from one DB to another DB. It will not do cache clearing on your CD servers. Which you need to do manually. But publishing will do all this for you! Transfer should be used only for worst case scenarios only!

Now, Dex and Gabe are really happy and they are enjoying their time! I’m sure they will keep sharing such things with us!

Happy Item Transferring! 🙂

Basic ways of troubleshooting EventQueue challenges

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! 🙂

Basics of Publishing multiple items programmatically

Challenge:

So long back posted one problem on SDN forum — http://sdn.sitecore.net/SDN5/Forum/ShowPost.aspx?PostID=45665

We have one functionality where users can select multiple items from different path for example :

/sitecore/content/A/1
/sitecore/content/A/4
/sitecore/content/A/5

Basically, we wanted to publish multiple items in one publishing Job. We asked to Sitecore support guys and they said:

In the comment for your forum post #45665 it completely correctly noted that currently in the Sitecore CMS you can publish either a single item or a whole subtree — not a list of items. You may want to use incremental publishing instead of smart publishing, because it publishes only recently changed items.

Using an incremental publishing was not an option for us. As we have Multisite Sitecore solution.

Solution:

Also, Sitecore support team suggested to use  Alex Shyba’s concept:

http://sitecoreblog.alexshyba.com/2010/07/hidden-feature-of-sitecore-62.html

Where we add item references programmatically. John is also fine with this approach on this thread : http://sdn.sitecore.net/forum//ShowPost.aspx?PostID=36069

So, you can also use it. But with few suggestions:

1.  It may affect performance. So, please test it throughly.

2. If you are using Multisite solution and have custom HTML cache clearing handler on publish:end:remote then make sure that you added same site’s items in one publish job.

Happy Multiple items publishing via code! 🙂