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

Performance regression of methods that compute user permissions

    XMLWordPrintable

Details

    Description

      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

      Attachments

        Issue Links

          Activity

            People

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

              Dates

                Created:
                Updated:
                Resolved: