In the last article, I explained how to create custom logs in Microsoft Dynamics 365 for Finance and Operations. In this lesson, learn how to expand custom logs to create D365 performance logs to help understand where performance may be improved. While performance improvement is a vast topic, this tutorial will show you how to make a log to track how long a specific piece of code takes to run. This gives you the information needed to know where more work should be done to improve the performance.
Why Track Performance?
Oftentimes, developers code complex processes that can take a long time to run. Even though those processes are often offloaded to be run by the batch server, code should be written with performance in mind. Furthermore, code that is written for better performance often uses fewer system resources, which can result in better performance overall and reduced costs.
Different Ways To Track Time
Before adding D365 Performance logs, it is important to understand the different ways of tracking the passage of time.
TimeNow
First, use the timeNow() global function to track how many seconds have passed since midnight. This is different than the methods on the UTCDateTimeUtil class, used for getting the date and time. But it is very useful for what we are trying to do.
In this example, the code gets the number of seconds since midnight, which is returned from the timeNow() method, and stores it into a variable. Then, the code simulates a process running, by telling the system to sleep for 5000 milliseconds, or 5 seconds. Finally, it gets the number of seconds passed midnight again, and uses the timeConsumed global function to produce a string saying how many hours, minutes, and seconds have elapsed.
static void testTimeNow()
{
int startTime, endTime;
startTime = timeNow();
sleep(5000); // Simulate a process
endTime = timeNow();
info(strFmt("Time elapsed with timenow(): %1", timeConsumed(startTime, endTime)));
}
Unfortunately, the timeNow() method only returns time in seconds. So it cannot be used to more accurately produce D365 performance logs. See this Microsoft documentation for more information.
WinAPI GetTickCount
In this next example, the WinAPI class has a method named getTickCount64(), which can return the milliseconds since midnight. This is more accurate than timeNow(), but is part of an older WinAPI class that may not always be supported in the future.
static void winApiTickCount()
{
int64 startTime, endTime;
int64 elapsed;
startTime = WinAPI::getTickCount64();
sleep(5000); // Simulate a process
endTime = WinAPI::getTickCount64();
elapsed = endTime - startTime;
info(strFmt("Time elapsed with winApp::getTickCount64(): %1 milliseconds", elapsed));
}
See this Microsoft documentation for more information.
StopWatch
Lastly, this example shows using the StopWatch .NET function for tracking the elapsed time. Helpfully, you can use .NET methods inside of Microsoft Dynamics 365 for Finance and Supply Chain. This is a modern approach that should be supported into the future.
static void stopWatchDotNetInterop()
{
System.Diagnostics.Stopwatch stopwatch = new System.Diagnostics.Stopwatch();
int64 elapsed;
stopwatch.Start();
sleep(5000); // Simulate a process
stopwatch.Stop();
elapsed = stopwatch.get_ElapsedMilliseconds();
info(strFmt("Time elapsed with System.Diagnostics.Stopwatch: %1 milliseconds", elapsed));
}
See this Microsoft documentation for more information.
Performance Tracking
Oftentimes, developers use D365 performance logs to help understand which path through code a process took when something goes wrong. However, there are more use cases for these types of records.
Use them to track the time passed between messages to understand which code sections are slow. These areas should then be further looked at for potential performance improvements. After the performance improvements are made, these particular log messages can be removed or left in.
Next, make the changes explained in the following sections, on top of the enhancements already made in D365 Custom Logs, to add performance logging.
Update The Table and Code
First, add three integer fields to the customLog table with the names: ‘Seconds‘, ‘SecondsSinceBegin‘, and ‘SecondsSinceLast‘.
Second, create a second logging method named logPerformance:
public static void logPerformance(LongDescription _message, RefRecId _refRecId, boolean _info = true)
{
customLog customLog;
customLog customLogLast; //The most recent custom log record inserted for this RefRecId
customLog customLogBegin; //The first custom log record inserted for this RefRecId
customLog.Message = _message;
customLog.LogRefRecId = _refRecId;
customLog.Seconds = timeNow(); //Store the current time
//Find the most recent custom log record that was inserted.
select firstOnly customLogLast
order by createdDateTime desc
where customLogLast.LogRefRecId == _refRecId;
if (customLogLast)
{
customLog.SecondsSinceLast = customLog.Seconds - customLogLast.Seconds;
}
else
{
//This is the first log record for this related record.
customLog.SecondsSinceLast = 0;
}
//Find the most recent insert with message 'Begin'
select firstOnly customLogBegin
order by createdDateTime desc
where customLogBegin.LogRefRecId == _refRecId
&& customLogBegin.Message == 'Begin';
if(customLogBegin)
{
customLog.SecondsSinceBegin = customLog.Seconds - customLogBegin.Seconds;
}
else
{
customLog.SecondsSinceBegin = 0;
}
if (customLog.Message == 'Begin')
{
customLog.SecondsSinceBegin = 0;
customLog.SecondsSinceLast = 0;
}
if (_info)
{
info(strFmt('SecondsSinceBegin: %1 SecondsSinceLast: %2 %3'
, customLog.SecondsSinceBegin
, customLog.SecondsSinceLast
, customLog.Message));
}
customLog.insert();
}
}
Use The Log
To use it, at the start of the process code, pass in the message ‘Begin’ to the logPerformance method. Note that it is not best practice to use a hard-coded string. Feel free to change it to a parameter. I used it to keep the example simple.
customLog::logPerformance("Begin", <your table record>.RecId);
The purpose of this message is to tell the system when it should start the timer. Alternatively, the code could be changed to look for the ‘first’ log with a LogRefRecId of the related value to use as the beginning record. However, there may be times when you rerun a process after it has failed. In those cases, you could delete all the logs first before rerunning the process. Therefore, use the above code to mark the beginning of a new run. Then, in your code, call logPerformance every time you wish to track how long a specific process took to run.
Example
For example, add another button to your transaction form, or modify an existing one you have. Next, override the clicked method, and specify the following code.
public void clicked()
{
super();
customLog::logPerformance("Begin", TransactionTable.RecId);
CustomLog::logPerformance(strfmt("Starting to process transaction ID %1", TransactionTable.TransactionId),TransactionTable.RecId);
//MyClass::ProcessTransaction(TransactionTable); //Put your code here to process the transaction.
sleep(5000); // Simulate a process
CustomLog::logPerformance(strfmt("Completed first part of processing transaction ID %1", TransactionTable.TransactionId), TransactionTable.RecId);
sleep(3000); // Simulate a process
CustomLog::logPerformance(strfmt("Finished processing transaction ID %1", TransactionTable.TransactionId), TransactionTable.RecId);
TransactionTable_ds.reread();
TransactionTable_ds.refresh();
CustomLog_ds.executeQuery();
}
Essentially, call the logPerformance method as many times as you want, in between methods, passing in a message explaining what is occurring.
Additionally, add calls to logPerformance to places deeper in the code to better understand which lines of code specifically are causing the performance issues.
Take Action
Now, look at the D365 custom log and see how many seconds passed between each message.
Then, review the code and, where possible, make improvements to the code, and rerun it to see if the performance of that specific piece of code has improved.
For example oftentimes, you can find a ‘while select‘ statement that has ‘where‘ clauses on fields that are not part of an index on the table. Add an index with those fields, rerun the process, and review the logs to see if the performance has improved.
Conclusion
It is extremely satisfying to see a process that used to take hours or minutes, now take seconds. In order to make these improvements a developer first needs to which part of the code is taking the most amount of time. The D365 performance logs shown in this article will provide this needed information. Once they know the time consuming code, they can focus their energy on seeing if it is possible to improve that code. After taking action, the D365 performance logs will help confirm the improvement. Finally, these logs can either be removed, or left in for ongoing insights.
