When DB Log files don’t help: Data Access Analysis Tips to boost Performance
If transaction times jump from less than one second to more than 60 seconds after a software upgrade, it is evident that there is a problem that needs investigation. This scenario was experienced by a customer with its time-tracking application. Our customer identified this performance regression while executing extensive performance tests prior to its production upgrade. The company’s “traditional” approach of analyzing these types of problems was analyzing application and database log files as well as infrastructure metrics such as CPU, Memory and Network Throughput. Our customer couldn’t find a single slow database query, nor were there any indications of an error in the log files. The infrastructure also seemed to be fine because the Application, the Database Server and the Network didn’t show any bottlenecks. Analyzing the End-to-End Transaction, such as the click on search, however revealed a problem which turned out to be a “data-driven” performance issue.
Problem: Loading and Processing Large Result Sets
The following screenshot shows parts of the PurePath highlighting where most of the time is spent within the transaction:
The SQL Statement to retrieve time tracking data executed in about 840ms. This doesn’t really indicate a hotspot for this transaction. loadDataStore however iterates through the ResultSet of this query. Looking at the PurePath details of that method execution shows that the continuous fetches of the next result sets is the real hotspot of this transaction. Most of the time is spent in I/O to retrieve the next batch of table rows and process this data.
Root Cause: Too Much Data for Test User
After consulting with the 3rd-party vendor of this application our customer came to the conclusion that the user account used in its load testing script had elevated privileges. When accessing a particular web page in the application this user was able to see time tracking data from all other users in the system. The implementation of this web page was such that it processed all data accessible by the user – instead of just accessing the data needed for display, e.g: for the first page of results.
Solution: “Real” User Account for Testing
Instead of using the special privileged user account the test scripts were modified to use a user account with “normal” privileges – this also reflected the real-life scenario. This reduced the transaction response time significantly—down from 61 seconds to 73 milliseconds– as shown in the following PurePath:
Unsurprisingly, the amount of data that is returned by a SQL Statement can have significant impact on transaction performance. There are however several lessons learned:
- SQL Log Files didn’t show this as a problem as they only reported the SQL Execution Time but not the individual Fetch and Processing times
- Testing needs to be done with real user accounts and not test, dummy or special privileged accounts
- Optimize access to large result sets by only processing what is really needed for display
If you are interested in more typical problem patterns check out the Top 8 Application Performance Landmines.