The Plugin Trace Viewer

This tool in the “industry standard” XrmToolBox was created to make the potential power of the Plugin Trace Log available to anyone. The log contains so much information that can make plugin analysis a lot easier, if presented in an intelligent way.

Key features

In Plugin Trace Viewer (PTV) the user is empowered by a few different key features:

More and relevant information

All relevant fields from the Plugin Trace Log is displayed; Correlation Id, Start Time, Duration, Operation, Plugin, Depth, Mode, Message, Entity. If an exception was thrown, PTV extracts the actual error message from the exception details text block and shows that directly in the Exception column. The Plugin Step that triggered the plugin is not related with a regular relationship, only the guid of the step is stored. PTV can still use this to display which Stage and Rank the step has. This is relevant when analyzing exact order of execution.

Smarter filtering

PTV allows filtering of all relevant information. This includes Execution Time, Plugin Type, Message, Entity, Operation Type, and Mode. You can also specify Execution Duration limits to identify long-running plugins or if there are many small atomic plugins that might benefit from being combined into fewer all-purpose plugins. It is possible to only show records from plugin executions that ended with an exception being thrown. Finally it is also possible to filter by Correlation Id. In the last article in this series, I will go deeper into working with Correlation Id to follow execution chains and how plugins correlate to each other.

Layout

The form layout of PTV provides an easy way to select which columns to display (right-click the table headers to select columns) and sizable quick-view windows for the Message Block and Exception Details multiline fields. It is possible to turn word wrap on or off for these. To maximize utilization of the form the Filter panel can be hidden.

Plugin Type Statistics

CRM collects life-time statistics for all plugins. This contains execution count, failure count, average execution time, and different crash numbers. When a log record is selected in PTV, the Plugin Type Statistics for that plugin is retrieved and displayed. To get an idea of how much impact a plugin has on the system, PTV also calculates average execution time per day as:
AvgExecTime * ExecCount / (ModifiedOn – CreatedOn)

Challenges

The Plugin Trace Log offers many opportunities for analyzing your plugins. There are however still a few challenges to overcome.

Exact Execution Time

All datetime fields in the log are displayed with date, hour and minute in CRM. In the database they are saved with second, which is displayed in Plugin Trace Viewer. Unfortunately the millisecond part of these timestamps are always zero. This makes it really difficult, and sometimes impossible, to know the exact order of execution between plugins. I have submitted a CRM Idea to also include milliseconds, vote this up if you would like to see that too!

Full Trust plugins

According to the SDK documentation claims that “Tracing is supported for sandboxed (partial trust) and full trust registered custom code”, but as a handful forum threads out there disappointingly conclude, this is not the case. This means you currently have to register your plugins in Sandboxed partial trust to get anything written to the Plugin Trace Log, with the limitations that means to your plugin execution. If I am not the only one who would like the functionality to live up to the expectations in the documentation, vote this CRM Idea up!

10k Limit on Message Block

The Message Block field is limited by CRM core code to 10k characters. When writing more text, it will be truncated from the top. For complex plugins with verbose logging, this poses a problem to the analysis. The reason to put a limit is quite viable, but I sure would like this limit to be configurable for my organization. There is another CRM Idea to make this happen!

Resetting Plugin Type Statistics

The Plugin Type Statistics entity only supports two messages; Retrieve and RetrieveMultiple. This means there is no way to reset the statistics for a plugin. After refactoring your code, it sure would be nice to be able to reset the statistics to evaluate behavior after the improvement. Vote to have Microsoft make this possible!

Demo 2 – PTV at a glance

In this demo I created a simple plugin that verifies that the fax field has not been entered on the entity triggering the plugin. The plugin uses the JonasPluginBase class to make development easier and get a lot of tracing for free. The code is really simplistic and looks like this:

    public class NoFaxPlease : JonasPluginBase.JonasPluginBase
    {
        public override void Execute(JonasPluginBag bag)
        {
            // Read updated value for Fax from Target entity
            string fax = bag.TargetEntity.GetAttributeValue("fax");

            if (!string.IsNullOrWhiteSpace(fax))
            {
                throw new InvalidPluginExecutionException($"Fax? Really? This is {DateTime.Now.Year}, you know... ");
            }

            // Get name of the record that triggered the plugin
            string recordName = bag.CompleteEntity.Name(bag, false);
            bag.Trace("No fax for {0}, this {1} is ready for the future.", recordName, bag.PluginContext.PrimaryEntityName);
        }
    }

The plugin produces an error message like this if enything is entered in the fax field:

Looking at the log in Plugin Trace Viewer shows this information:

10:30:30.007	*** Enter
10:30:30.007	[JPB] Context details:
  Step:  eXtremePlugins.NoFaxPlease: Update of  any Entity
  Msg:   Update
  Stage: 10
  Mode:  0
  Depth: 1
  Corr:  c3d58faf-f9ed-496d-b53d-63e6711bfe89
  Type:  account
  Id:    1bcc51ab-58fe-e611-80fb-5065f38b2601
  User:  9cc6ecfd-cce1-4bd5-8832-20e476f776e1
  IUser: 9cc6ecfd-cce1-4bd5-8832-20e476f776e1

10:30:30.085	[JPB] Incoming account
  accountid = 1bcc51ab-58fe-e611-80fb-5065f38b2601 (Guid)
  fax       = 123456 (String)

10:30:30.085	BEGIN Microsoft.Xrm.Sdk.InvalidPluginExecutionException
10:30:30.085	  [JPB] Microsoft.Xrm.Sdk.InvalidPluginExecutionException: Fax? Really? This is 2017, you know... 
   at eXtremePlugins.NoFaxPlease.Execute(JonasPluginBag bag)
   at JonasPluginBase.JonasPluginBase.Execute(IServiceProvider serviceProvider)
10:30:30.085	END Microsoft.Xrm.Sdk.InvalidPluginExecutionException
10:30:30.085	[JPB] Internal execution time: 6 ms
10:30:30.085	*** Exit

The JonasPluginBase code is available at GitHub and as NuGet package. The plugin sample is available at GitHub.

In the fourth article in this series, I will dig deep into the possibilities of tracing execution chains, events triggering events, and how to follow the breadcrumb trail in our logs using the Correlation Id.