Details
-
Bug
-
Resolution: Fixed
-
Highest
-
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
-
3
-
Severity 2 - Major
-
40
-
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:
- 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
- relates to
-
-
- Closed
-
-
-
- Closed
-
(1 mentioned in)