Uploaded image for project: 'Bitbucket Data Center'
  1. Bitbucket Data Center
  2. BSERV-13056

Performance regression of methods that compute user permissions

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Highest Highest
    • 7.17.3, 7.18.2
    • 7.12.1, 7.13.1, 7.14.1, 7.16.0, 7.15.2, 7.17.0, 7.18.0, 7.16.1, 7.17.1
    • Database - Permissions

      Issue Summary

      After upgrading to Bitbucket 7.12 - 7.18, requests are slow. Inspecting profiling logs shows a 8-10x performance degradation in methods that compute permissions for users and groups. For example, the REST request ( GET https://<base-url>/rest/api/latest/dashboard/pull-requests?participant=user&role=AUTHOR ) produces the following profiling logs:

      In Bitbucket 7.11: 

      2021-11-24 07:14:16,646 | http-nio-7990-exec-4 | @10PGJ1Yx434x49x0 | user | -
[6815.2ms] - "GET /rest/api/latest/dashboard/pull-requests HTTP/1.1"
 [4816.0ms] - Authentication org.springframework.security.authentication.AuthenticationProvider.authenticate(Authentication)
  [167.3ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-crowd-sso:crowdSsoAuthHandler
   [155.2ms] - CaptchaTicket com.atlassian.stash.internal.user.CaptchaService.checkCaptcha(String,CaptchaResponse)
  [49.5ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-access-tokens:accessTokenHttpAuthHandler
   [29.8ms] - ApplicationUser com.atlassian.bitbucket.user.UserService.getUserByName(String)
    [28.2ms] - InternalNormalUser com.atlassian.stash.internal.user.ApplicationUserDao.findByName(String)
  [266.8ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-authentication:crowdHttpAuthHandler
   [266.7ms] - AuthenticationResult com.atlassian.stash.internal.user.CaptchaService.authenticateWithCaptcha(CaptchaTicket,UncheckedOperation)
    [9.3ms] - InternalNormalUser com.atlassian.stash.internal.user.ApplicationUserDao.loadUser(User)
  [15.8ms] - Map com.atlassian.stash.internal.user.ProjectPermissionDao.getDefaultPermissions()
  [52.2ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest)
  [27.2ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByGroup(String,PageRequest)
  [361.7ms] [count: 7, avg: 51.7ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByUserId(Integer,PageRequest)
 [64.6ms] - Page com.atlassian.bitbucket.pull.PullRequestService.search(PullRequestSearchRequest,PageRequest)
  [10.8ms] - Set com.atlassian.bitbucket.user.UserService.getUsersByName(Set,boolean)
   [10.5ms] - Set com.atlassian.stash.internal.user.ApplicationUserDao.findByNames(Set)
  [42.2ms] - Page com.atlassian.stash.internal.pull.PullRequestDao.search(PullRequestSearchCriteria,PageRequest,Predicate)

      In Bitbucket 7.12: 

      2021-11-24 07:22:14,068 | http-nio-7990-exec-7 | @10PGJ1Yx442x61x0 | user | -
[6054.6ms] - "GET /rest/api/latest/dashboard/pull-requests HTTP/1.1"
 [3409.5ms] - Authentication org.springframework.security.authentication.AuthenticationProvider.authenticate(Authentication)
  [270.6ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-crowd-sso:crowdSsoAuthHandler
   [262.4ms] - CaptchaTicket com.atlassian.stash.internal.user.CaptchaService.checkCaptcha(String,CaptchaResponse)
  [11.8ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-git-lfs:git-lfs-jwt-auth-handler
  [49.7ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-access-tokens:accessTokenHttpAuthHandler
   [26.3ms] - ApplicationUser com.atlassian.bitbucket.user.UserService.getUserByName(String)
    [23.9ms] - InternalNormalUser com.atlassian.stash.internal.user.ApplicationUserDao.findByName(String)
  [366.8ms] - attemptAuthentication - com.atlassian.bitbucket.server.bitbucket-authentication:crowdHttpAuthHandler
   [343.9ms] - AuthenticationResult com.atlassian.stash.internal.user.CaptchaService.authenticateWithCaptcha(CaptchaTicket,UncheckedOperation)
    [11.7ms] - InternalNormalUser com.atlassian.stash.internal.user.ApplicationUserDao.loadUser(User)
  [12.6ms] - Map com.atlassian.stash.internal.user.ProjectPermissionDao.getDefaultPermissions()
  [82.8ms] - Page com.atlassian.bitbucket.user.UserService.findGroupsByUser(String,PageRequest)
  [39.7ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByGroup(String,PageRequest)
  [2476.0ms] [count: 7, avg: 353.7ms] - Page com.atlassian.stash.internal.user.EffectivePermissionDao.findByUserId(Integer,PageRequest)
 [80.0ms] - Page com.atlassian.bitbucket.pull.PullRequestService.search(PullRequestSearchRequest,PageRequest)
  [8.1ms] - Set com.atlassian.bitbucket.user.UserService.getUsersByName(Set,boolean)
   [7.9ms] - Set com.atlassian.stash.internal.user.ApplicationUserDao.findByNames(Set)
  [58.2ms] - Page com.atlassian.stash.internal.pull.PullRequestDao.search(PullRequestSearchCriteria,PageRequest,Predicate)

      Comparing the time taken by com.atlassian.stash.internal.user.EffectivePermissionDao.findByUserId(Integer,PageRequest) in two versions above, a performance degradation of ~6.8x is observed (2476 vs 361.7 ms). This may result in several other issues being observed, for example:

       

      1. Threads being blocked with a stack similar to: 
         java.lang.Thread.State: BLOCKED (on object monitor)
	at com.atlassian.cache.memory.DelegatingCachedReference.getUnderLock(DelegatingCachedReference.java:103)
	- waiting to lock <0x00000003c6011178> (a com.atlassian.cache.memory.DelegatingCachedReference)
	at com.atlassian.cache.memory.DelegatingCachedReference.get(DelegatingCachedReference.java:88)
	at com.atlassian.cache.hazelcast.HazelcastAsyncHybridCachedReference.get(HazelcastAsyncHybridCachedReference.java:65)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider.getGroupsPermissions(PreloadingGrantedPermissionVoterProvider.java:266)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider.access$300(PreloadingGrantedPermissionVoterProvider.java:75)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$NormalUserPermissionVoterCalculator.calculate(PreloadingGrantedPermissionVoterProvider.java:360)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.recalculate(PreloadingGrantedPermissionVoterProvider.java:463)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.getVoter(PreloadingGrantedPermissionVoterProvider.java:434)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.vote(PreloadingGrantedPermissionVoterProvider.java:422)
	at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:70)
	at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:46)
	at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:609)
	at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:597)

      These threads are blocked waiting for another thread to populate the group permissions cache entry. There will then be a thread building the cache entry, most likely blocked in a database request. For example:

      <snip>
	at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
<snip>
	at com.atlassian.stash.internal.user.HibernateEffectivePermissionDao.findAllByGroups(HibernateEffectivePermissionDao.java:61)
<snip>
	- locked <0x00000003c6011178> (a com.atlassian.cache.memory.DelegatingCachedReference)
	at com.atlassian.cache.memory.DelegatingCachedReference.get(DelegatingCachedReference.java:88)
	at com.atlassian.cache.hazelcast.HazelcastAsyncHybridCachedReference.get(HazelcastAsyncHybridCachedReference.java:65)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider.getGroupsPermissions(PreloadingGrantedPermissionVoterProvider.java:266)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider.access$300(PreloadingGrantedPermissionVoterProvider.java:75)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$NormalUserPermissionVoterCalculator.calculate(PreloadingGrantedPermissionVoterProvider.java:360)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.recalculate(PreloadingGrantedPermissionVoterProvider.java:463)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.getVoter(PreloadingGrantedPermissionVoterProvider.java:434)
	at com.atlassian.stash.internal.permission.PreloadingGrantedPermissionVoterProvider$RecalculatingPermissionVoter.vote(PreloadingGrantedPermissionVoterProvider.java:422)
	at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:70)
	at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:46)
	at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:609)
	at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:597)

       

      2. git operations failing intermittently when a repository is deleted, producing a stack trace like so:

       2021-11-24 17:56:25,260 ERROR [http-nio-7101-exec-152]  o.a.c.c.C.[.[.[/].[default] Servlet.service() for servlet [default] in context with path [] threw exception
com.atlassian.cache.CacheException: javax.persistence.EntityNotFoundException: No row with the given identifier exists: [com.atlassian.stash.internal.repository.InternalRepository#256624]
        at com.atlassian.cache.memory.DelegatingCache.get(DelegatingCache.java:212)
        at com.atlassian.cache.memory.DelegatingCache.get(DelegatingCache.java:163)
        at com.atlassian.cache.hazelcast.HazelcastAsyncHybridCache.get(HazelcastAsyncHybridCache.java:79)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider.getUserPermissions(DefaultGrantedPermissionVoterProvider.java:288)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider.access$600(DefaultGrantedPermissionVoterProvider.java:78)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider$NormalUserPermissionVoterCalculator.calculate(DefaultGrantedPermissionVoterProvider.java:378)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider$RecalculatingPermissionVoter.recalculate(DefaultGrantedPermissionVoterProvider.java:463)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider$RecalculatingPermissionVoter.getVoter(DefaultGrantedPermissionVoterProvider.java:434)
        at com.atlassian.stash.internal.permission.DefaultGrantedPermissionVoterProvider$RecalculatingPermissionVoter.vote(DefaultGrantedPermissionVoterProvider.java:422)
        at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:70)
        at com.atlassian.stash.internal.permission.CompositePermissionVoter.vote(CompositePermissionVoter.java:46)
        at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:609)
        at com.atlassian.stash.internal.user.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:597)
        at com.atlassian.stash.internal.user.PermissionServiceImpl.hasGlobalPermission(PermissionServiceImpl.java:117)
        at com.atlassian.stash.internal.spring.security.PluginAuthenticationProvider.lambda$authenticate$0(PluginAuthenticationProvider.java:53

      Rerunning the request usually helps in this case.

      The root cause is a change introduced in 7.12. Also, in Bitbucket 7.16, the implementation of GrantedPermissionVoterProvider was replaced with a new implementation in order to improve performance problems seen (e.g. BSERV-12166). In 7.16.0, 7.17.0 and 7.17.1 both implementations exist and it is possible to switch to the old implementation. However in 7.18.0 only the new implementation exists.

      Workaround

      • The issue can be worked around by restricting the number of repositories a user has explicit permissions to (the issue was observed when a user was granted permissions to ~1.2k repositories explicitly). One of the ways to do this is to roll up a user's permissions from the repository to the project level.
      • For Bitbucket 7.16 and 7.17, the issue may be mitigated by setting the following property in bitbucket.properties and restarting Bitbucket DC nodes:
      dark-features.permissions.cache-all-groups=false

              csubraveti Chandravadan
              behumphreys Ben Humphreys
              Votes:
              2 Vote for this issue
              Watchers:
              7 Start watching this issue

                Created:
                Updated:
                Resolved: