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)