Sitecore Profiling and Tracing

It's been a while since I've posted. I have a couple of bigger subjects on the spike, but for now here's a quick word about Sitecore profiling and tracing.

Have you ever had to debug a problem with a Sitecore page and you wind up slogging through the log, trying to find the related error? Or have you ever wondered which of your renderings or sublayouts might be causing performance issues? Or maybe you have custom logic in a pipeline processor, and you wish there was an easy way to emit debugging or performance information?

There are a couple of underutilized features in Sitecore that can be a real time saver in situations like this: Sitecore.Diagnostics.Tracer and Sitecore.Diagnostics.Profiler. These classes are sitting right next to the much-used Sitecore.Diagnostics.Log class, but are often overlooked. Both of these classes allow you to emit information directly to the page when in debug mode. This is a far more convenient and useful way to do debugging than writing to the Sitecore log.

The Profiler class is useful for tracking the progress of the page rendering cycle, and for gathering performance data about the components and code being executed. It has the usual Info, Warning and Error static methods you are probably familiar with from the Log class, but the real gems here are the StartOperation and EndOperation methods. With them, you can gather valuable performance data about parts of the rendering process, including both large chunks of a process and nested inner pieces of the process. For example, the Arke MetaTag Manager  module emits quite a bit of information about it's internal workings to the debugger.

The information provided not only helps us understand the performance impact of this process, but also helps us troubleshoot when we suspect that a tag is not being gathered properly.

To output this information, it's a simple matter of adding a two lines of code. For example, this is the Process method used for the CustomTag pipeline processor:

public void Process(InjectMetaTagsPipelineArgs args)

{

  Sitecore.Diagnostics.Profiler.StartOperation(

    "Adding custom tag '" + GetSignatureName() + "'"

    );

  try

  {

    Assert.ArgumentNotNullOrEmpty(

      TypeSignature, 

      "Class not supplied"

      );

    args.MetaTags.Add(ReflectionUtil.GetCustomTag(TypeSignature));

  }

  catch (Exception ex)

  {

    Sitecore.Diagnostics.Tracer.Error(

      "CustomTag failed.", 

      ex

      );

    Sitecore.Diagnostics.Log.Error(

      "CustomTag failed.", 

      ex, 

      "CustomTag"

      );

  }

  finally

  {

    Sitecore.Diagnostics.Profiler.EndOperation();

  }

}

Sitecore will nest sets of profiling blocks, which makes it easy to trace through a process to see where a problem or performance hit may be.

The other handy class for "in-page" debugging is the Tracer class. Again , this class has the familiar Info, Warning and Error static methods, but the output from these methods is written to the "Trace" section of the page debugger. I use these methods for writing out error or info strings much the way I would to the Sitecore Log, but they're written to the page itself, where troubleshooting is much easier. It's always nice to just be able to turn on the debugger to see this info instead of having to search through the log file.

Again, looking at the sample code above, note that the "catch" statements include a line of code to write the error to the tracer, which would yield this:

That beats searching for the error on the log file ... or worse, throwing a "yellow screen".

Happy tracing!