As I promised, this post will be dedicated to some real life practice. We’ll try to find the bottle neck in one document save process.
The principles and structures for ERP performance were described in the previous posts you can find them in my blog.
The work starts when we receive a report and see that we’ve got some problems:
Document 1 is ok – its trend is falling. But Document 2 is a real issue – it has problems with save duration nearly every day. So, we need to drill throw in order to find the bottle neck in the save logic of this document. All tests will not be performed on development environment with the help of automated unit tests that will open, made modifications and save the problem document for about 500 times. We care for the percentage of each method in total save duration, so we do not need real production load and real production environment. When we fixed the most long-running procedure on development environment in 90% it would cause positive changes on production also.
So, let’s start. The detailed log will be collected for all iterations the same way and would look like the following:
- Each method must be wrapped in time measurement sections:
- The result XML is stored in database. So each SAVE record in statistics database would have XML field with all needed for further analysis details. The XML is:
<ROOT>
<Open
AfterClearCashes="0"
AfterPreviousObjectOpen="312,5"
AfterOnPreOpen="0"
AfterOpenItem="62,5"
AfterGetRights="15,625"
AfterOnPostOpen="125" />
</ROOT>
- Then results are transferred to MS Excel and in Pivot table we can easily find the method that takes maximum percentage on total save duration.
So, let’s try to explore out document and find the bottleneck.
On the first iteration we will log the highest level of save procedure. In this case all logic for logging is already implemented and we have only to turn on special flag. Start unit tests, get results, transfer them to Excel and below you can find what we’ve got in Pivot:
Great, we’ve got one candidate that takes about 45% of document save time. Let’s drill through and log the AfterSaveItem method. For this purpose we have to wrap in all methods in after save procedure, run unit tests one more time, move results to Excel and analyze:
Here it is. 31% from 45% takes one method – WriteComments. It seems to me that we have found our issue. After code analysis, we see that inside the method the SQL stored procedure is called and it seems that it works not so good as it has to. You can start optimizing it right now, but I prefer to collect the SQL stored procedure executions with the help of MS Profiler (to find the most hard combinations of the parameters) and only then initiate optimization work.
In this case the issue was not in the stored procedure, but in the logic. This method was executed during each save of the document, but has to be called only during document creation or deletion of the position in the document. Making these changes has accelerated save duration and document was back in targets.
To sum up, it’s usually not enough SQL Server or Windows Server tools to log why some blocks of the system have poor performance. You need some internal mechanisms to look for issues and performance bottlenecks. In the series I’ve tried to describe all aspects а ERP system performance measurement and hope this information would be useful.
In the next post I will speak briefly how to ping system availability and close this theme.