Missed the first articles? Read the first and the second.
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.
In Plugin Trace Viewer (PTV) the user is empowered by a few different key features:
More and relevant informationAll 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.
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.
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 StatisticsCRM 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)
The Plugin Trace Log offers many opportunities for analyzing your plugins. There are however still a few challenges to overcome.
Exact Execution TimeAll 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!
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 BlockThe 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!
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!
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.
Labels: Community, Conferences, Open Source, Plugin, Tools