Details
-
Suggestion
-
Resolution: Fixed
-
None
Description
Problem Definition
The analysis of the profiling logs can be more difficult in cases when:
- the same request is performed multiple times
- such request completes very quickly
In the example below, we can see that the /rest/api/latest/users request completed in over 10 seconds but the individual lines don't sum up to that value:
[10383ms] - "GET /rest/api/latest/users HTTP/1.1" [6ms] - ApplicationUser com.atlassian.bitbucket.user.UserService.getUserById(int) [7ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest) ... 268 lines of [1ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByGroup(String,PageRequest)
What is happening here is that many com.atlassian.stash.internal.user.EffectivePermissionDao.findByGroup operations are being performed but, because they are faster than 1ms, they are not logged.
The problem with the current implementation is:
- it is not clear why the request is taking that amount of time
- operations faster than 1ms are not logged
- we cannot determine how many fast operations are being performed and how long they take on average
Suggested Solution
Combine adjacent frames for the same timer and:
- show their count
- add a calculate average of each frame
The profiling log above would now look like the following:
[10383ms] - "GET /rest/api/latest/users HTTP/1.1" [6ms] - ApplicationUser com.atlassian.bitbucket.user.UserService.getUserById(int) [7ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest) [10370ms] [count: 1728, avg: 0.6ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByGroup(String,PageRequest)