Slow performance (30+ seconds) when adding user to a group in large organization

[IT-AlexKor]

Description

Slow performance (7 minutes) on UI/API when adding/removing team in large organization (2000+ repos)

Steps to reproduce

1. Create organization with 2000+ repos
2. Create new team with:

• Repository access = All repos
• Permission = General access
• Access to sections = all to Read
• External Wiki/Issues = disabled

3. Add new user to this team
4. Wait 30-35 seconds until it done

Gitea Version

1.16.3

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

No response

Screenshots

No response

Git Version

2.21.0

Operating System

CentOS Linux 7 (Core)

How are you running Gitea?

APP_NAME = -ERASED-
RUN_USER = git
RUN_MODE = prod

[security]
INTERNAL_TOKEN = -ERASED-
INSTALL_LOCK = true
SECRET_KEY = -ERASED-
PASSWORD_HASH_ALGO = pbkdf2
DISABLE_GIT_HOOKS = false

[database]
DB_TYPE = postgres
HOST = -ERASED-
NAME = -ERASED-
USER = -ERASED-
PASSWD = -ERASED-
SCHEMA =
SSL_MODE = disable
CHARSET = utf8
PATH = /var/lib/gitea/data/gitea.db
LOG_SQL = false

[repository]
ROOT = /var/lib/gitea/data/gitea-repositories

[server]
SSH_DOMAIN = -ERASED-
DOMAIN = -ERASED-
HTTP_PORT = 3000
ROOT_URL = -ERASED-
DISABLE_SSH = false
SSH_PORT = 22
LFS_START_SERVER = true
LFS_JWT_SECRET = -ERASED-
OFFLINE_MODE = false

[lfs]
PATH = /var/lib/gitea/data/lfs

[mailer]
ENABLED = true
HOST = -ERASED-
FROM = -ERASED-
USER =
PASSWD =

[service]
REGISTER_EMAIL_CONFIRM = false
ENABLE_NOTIFY_MAIL = true
DISABLE_REGISTRATION = true
ALLOW_ONLY_EXTERNAL_REGISTRATION = false
ENABLE_CAPTCHA = false
REQUIRE_SIGNIN_VIEW = true
DEFAULT_KEEP_EMAIL_PRIVATE = false
DEFAULT_ALLOW_CREATE_ORGANIZATION = false
ENABLE_TIMETRACKING = false
DEFAULT_ENABLE_TIMETRACKING = false
NO_REPLY_ADDRESS = noreply.localhost

[picture]
DISABLE_GRAVATAR = false
ENABLE_FEDERATED_AVATAR = true

[openid]
ENABLE_OPENID_SIGNIN = false
ENABLE_OPENID_SIGNUP = false

[session]
PROVIDER = file

[log]
MODE = file,console
LEVEL = info
ROOT_PATH = /var/lib/gitea/log
ROUTER = console,file

[metrics]
ENABLED = true

[mirror]
MIN_INTERVAL = 1m

[indexer]
ISSUE_INDEXER_TYPE = elasticsearch
ISSUE_INDEXER_CONN_STR = http://-ERASED-
ISSUE_INDEXER_NAME = gitea_issues
ISSUE_INDEXER_PATH = indexers/issues.bleve
REPO_INDEXER_ENABLED = true
REPO_INDEXER_TYPE = elasticsearch
REPO_INDEXER_CONN_STR = http://-ERASED-
REPO_INDEXER_NAME = gitea_codes
REPO_INDEXER_PATH = indexers/repos.bleve
UPDATE_BUFFER_LEN = 20
MAX_FILE_SIZE = 1048576
REPO_INDEXER_INCLUDE =
REPO_INDEXER_EXCLUDE = resources/bin/**
STARTUP_TIMEOUT = 30s

[git.timeout]
MIGRATE = 1800
MIRROR = 600

Database

PostgreSQL

[lunny]

Could you provide logs?

[mscherer]

Given the code, I would say that's likely something on https://github.com/go-gitea/gitea/blob/e69b7a92ed/models/org_team.go#L969 . The more repos on a team, the more slow it would be due to the looping over all repos.

[IT-AlexKor]

Here the part of Logs:

2022/03/27 06:53:29 ...s/issue_stopwatch.go:76:GetUserStopwatches() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (stopwatch.user_id = $1) [6] - 4.553345ms
2022/03/27 06:53:31 ...ices/auth/session.go:48:SessionUser() [T] Session Authorization: Found user[6]
2022/03/27 06:53:31 models/user/user.go:955:GetUserByIDEngine() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [6] - 3.197087ms
2022/03/27 06:53:31 ...ices/auth/session.go:64:SessionUser() [T] Session Authorization: Logged in user 6:<ERASED>
2022/03/27 06:53:31 ...s/issue_stopwatch.go:103:hasUserStopwatch() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [6] - 2.67141ms
2022/03/27 06:53:31 ...orm@v1.2.5/engine.go:1139:Get() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "lower_name"=$1 AND "type"=$2 LIMIT 1 [<ERASED> 1] - 3.160082ms
2022/03/27 06:53:31 models/org.go:76:loadTeams() [I] [SQL] SELECT "id", "org_id", "lower_name", "name", "description", "authorize", "num_repos", "num_members", "includes_all_repositories", "can_create_org_repo" FROM "team" WHERE (org_id=$1) ORDER BY CASE WHEN name LIKE 'Owners' THEN '' ELSE name END [10] - 4.32519ms
2022/03/27 06:53:31 models/org.go:76:loadTeams() [I] [SQL] SELECT "id", "org_id", "lower_name", "name", "description", "authorize", "num_repos", "num_members", "includes_all_repositories", "can_create_org_repo" FROM "team" WHERE (org_id=$1) ORDER BY CASE WHEN name LIKE 'Owners' THEN '' ELSE name END [10] - 2.949536ms
2022/03/27 06:53:31 ...orm@v1.2.5/engine.go:1139:Get() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "lower_name"=$1 LIMIT 1 [<ERASED>] - 4.261795ms
2022/03/27 06:53:31 models/org_team.go:225:IsMember() [I] [SQL] SELECT * FROM "team_user"  WHERE (org_id=$1) AND (team_id=$2) AND (uid=$3) LIMIT 1 [10 15 6] - 2.65574ms
2022/03/27 06:53:31 models/org_team.go:896:AddTeamMember() [I] [SQL] SELECT * FROM "team_user"  WHERE (org_id=$1) AND (team_id=$2) AND (uid=$3) LIMIT 1 [10 15 6] - 2.40616ms
2022/03/27 06:53:31 models/org.go:696:AddOrgUser() [I] [SQL] SELECT * FROM "org_user"  WHERE (uid=$1) AND (org_id=$2) LIMIT 1 [6 10] - 2.610167ms
2022/03/27 06:53:31 models/org_team.go:240:getRepositories() [I] [SQL] SELECT * FROM "repository" INNER JOIN "team_repo" ON repository.id = team_repo.repo_id WHERE (team_repo.team_id=$1) ORDER BY repository.name [15] - 25.338264ms
2022/03/27 06:53:32 ...ers/web/org/teams.go:142:TeamsAction() [I] [SQL] BEGIN TRANSACTION [] - 943.199µs
2022/03/27 06:53:32 models/org_team.go:918:AddTeamMember() [I] [SQL] INSERT INTO "team_user" ("org_id","team_id","uid") VALUES ($1,$2,$3) RETURNING "id" [10 15 6] - 2.173249ms
2022/03/27 06:53:32 ...ers/web/org/teams.go:142:TeamsAction() [I] [SQL] UPDATE "team" SET "num_members" = "num_members" + $1 WHERE "id"=$2 [1 15] - 2.224103ms
2022/03/27 06:53:32 ...epo_collaboration.go:132:getCollaboration() [I] [SQL] SELECT "id", "repo_id", "user_id", "mode", "created_unix", "updated_unix" FROM "collaboration" WHERE "repo_id"=$1 AND "user_id"=$2 LIMIT 1 [704 6] - 2.505197ms
2022/03/27 06:53:32 models/user/user.go:955:GetUserByIDEngine() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [10] - 2.649132ms
2022/03/27 06:53:32 models/access.go:207:recalculateUserAccess() [I] [SQL] SELECT * FROM "team" INNER JOIN "team_repo" ON team_repo.team_id = team.id INNER JOIN "team_user" ON team_user.team_id = team.id WHERE (team.org_id = $1) AND (team_repo.repo_id=$2) AND (team_user.uid=$3) [10 704 6] - 3.683082ms
2022/03/27 06:53:32 models/org_team.go:269:AddMember() [I] [SQL] DELETE FROM "access" WHERE "user_id"=$1 AND "repo_id"=$2 [6 704] - 1.987403ms
2022/03/27 06:53:32 models/org_team.go:932:AddTeamMember() [I] [SQL] INSERT INTO "access" ("user_id","repo_id","mode") VALUES ($1,$2,$3) RETURNING "id" [6 704 admin] - 2.087523ms
2022/03/27 06:53:32 models/repo/watch.go:47:GetWatch() [I] [SQL] SELECT "id", "user_id", "repo_id", "mode", "created_unix", "updated_unix" FROM "watch" WHERE "user_id"=$1 AND "repo_id"=$2 LIMIT 1 [6 704] - 1.925607ms
...
... Same 2000+ blocks from "..epo_collaboration.go:132:getCollaboration()" to "models/repo/watch.go:47:GetWatch() "
...
2022/03/27 06:54:09 modules/web/route.go:74:func1() [I] [SQL] COMMIT [] - 2.299658ms
2022/03/27 06:54:09 ...ices/auth/session.go:48:SessionUser() [T] Session Authorization: Found user[6]

2022/03/27 06:54:09 ...ices/auth/session.go:64:SessionUser() [T] Session Authorization: Logged in user 6:<ERASED>
2022/03/27 06:54:09 ...s/issue_stopwatch.go:103:hasUserStopwatch() [I] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [6] - 3.275542ms
2022/03/27 06:54:09 ...orm@v1.2.5/engine.go:1139:Get() [I] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "lower_name"=$1 AND "type"=$2 LIMIT 1 [<ERASED> 1] - 3.046708ms
2022/03/27 06:54:09 models/org.go:76:loadTeams() [I] [SQL] SELECT "id", "org_id", "lower_name", "name", "description", "authorize", "num_repos", "num_members", "includes_all_repositories", "can_create_org_repo" FROM "team" WHERE (org_id=$1) ORDER BY CASE WHEN name LIKE 'Owners' THEN '' ELSE name END [10] - 4.310003ms
2022/03/27 06:54:10 models/org.go:76:loadTeams() [I] [SQL] SELECT "id", "org_id", "lower_name", "name", "description", "authorize", "num_repos", "num_members", "includes_all_repositories", "can_create_org_repo" FROM "team" WHERE (org_id=$1) ORDER BY CASE WHEN name LIKE 'Owners' THEN '' ELSE name END [10] - 3.413906ms
2022/03/27 06:54:10 models/org_team.go:843:getTeamUsersByTeamID() [I] [SQL] SELECT "id", "org_id", "team_id", "uid" FROM "team_user" WHERE (team_id=$1) [15] - 2.855791ms

2022/03/27 06:54:10 ...s/context/context.go:198:HTML() [D] Template: org/team/members

[6543]

@IT-AlexKor can you test latest state of #19227 ?

[IT-AlexKor]

@6543 sorry, but it may be complicated, because it's a single production instance...

[lunny]

I have tested locally. Add member should be very fast, but I need to know if the result is right. Have no idea to optimize remove member from team.