In Pentia we have created a new service – Pentia Professional Services, where we offer our deep knowledge of and experiences with Sitecore. The purpose of this service is a bit like Sitecore Professional Services. We offer to help clients and partners with architecture, codereviews, performance testing and debugging Sitecore solutions. To differentiate us from Sitecore Professional Services we focus on the custom solution, where Sitecore focuses on the product.
A couple of weeks ago I was assigned to a task, where a client experienced that the Sitecore backend were performing really bad. Issues like these have always been harder to debug then frontend performance issues, as there are very few indicators to which process, is making the solution stall. Is it a scheduled task? Is it a custom pipeline? Is it an event hookup? Etc. etc.
Well on this particular task I found a rather new entry type in the log. Sitecore has implemented a new counter – the LongRunningOperationWatcher. This class is used to log entries like this:
Long running operation: Running Validation Rules
This is a great indicator and makes it easier to debug the backend. The class is called with a threshold, a message and some custom parameters, which are outputted in the log entry if the threshold timer is exceeded when the object is disposed. It is used in different methods throughout the kernel – for instance when validating different validation rules and in different pipelines. I can only hope that Sitecore will extend it to more operations and pipelines. Further it is great to use yourself, when creating a custom scheduled task, which might run wild.
After analyzing the log file for the client, I found that the “Long operation: Running validation rules” entry came up constantly, which told me, that either they had some custom validations, which were quite heavy on performance or that the server couldn’t bare the load from the standard validations.