Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open Pull-Requests view with > 500 organizations need more than 1 minute #15412

Closed
1 of 6 tasks
somera opened this issue Apr 11, 2021 · 31 comments · Fixed by #16099 or #16839
Closed
1 of 6 tasks

Open Pull-Requests view with > 500 organizations need more than 1 minute #15412

somera opened this issue Apr 11, 2021 · 31 comments · Fixed by #16099 or #16839
Labels
performance/speed performance issues with slow downs type/bug
Milestone

Comments

@somera
Copy link

somera commented Apr 11, 2021

  • Gitea version (or commit ref): 1.14.0
  • Git version:
  • Operating system: 20.04.2
  • Database (use [x]):
    • PostgreSQL
    • MySQL
    • MSSQL
    • SQLite
  • Can you reproduce the bug at https://try.gitea.io:
    • Yes (provide example URL)
    • No
  • Log gist:

Description

This with 1 minute is on my internal mini-server configuration.

I try to analyze what are you doing after I open the Pull-Requests link.

image

What I see.

First this PostgreSQL query:

explain analyze SELECT "repository"."id" FROM "repository" INNER JOIN "team_user" ON repository.owner_id = team_user.org_id INNER JOIN "team_repo" ON ('true' != 'false' and repository.is_private != 't') OR (team_user.team_id = team_repo.team_id AND repository.id = team_repo.repo_id) WHERE (team_user.uid = '1') GROUP BY repository.id

image

Which needs ~7 seconds on my NUC (https://ark.intel.com/content/www/us/en/ark/products/126137/intel-nuc-kit-nuc7pjyh.html -> I'm running here Gitea 1.14.0, PostgreSQL 13, Nginx, InfluxDB, Grafana), And after the first query I see a lot small PostgreSQL queries. I think one for every organization.

And when I choose other organization from the long list

image

I see > 500 http requests to the Gitea server

image

Looks like the process is "complicated" and not scalable for a lot of organizations and repos. Cause I have no pull requests on my Gitea instance

image

I think you should return back only all organizations which has pull requests. In my case: no one. Just the info: you dind't have any pull requests.

But this "problem" has only user with a lot of organizations and repos.

Am I right?

@lunny lunny added type/bug performance/speed performance issues with slow downs labels Apr 12, 2021
@lunny lunny added this to the 1.14.1 milestone Apr 12, 2021
@somera somera changed the title [Question] Open Pull-Requests view with > 500 organizations nee more than 1 minute [Question] Open Pull-Requests view with > 500 organizations need more than 1 minute Apr 12, 2021
@nsmith5
Copy link
Contributor

nsmith5 commented Apr 13, 2021

This looks like the offending call stack for anyone interested:

  • buildIssueOverview(ctx, models.UnitTypePullRequests)
  • userRepoIDs, err := getActiveUserRepoIDs(ctxUser, team, unitType)
  • userRepoIDs, err = ctxUser.GetActiveAccessRepoIDs(unitType)
  • ids2, err := u.GetActiveOrgRepositoryIDs(units...)
  • gitea/models/user.go

    Lines 547 to 565 in 66f0fd0

    func (u *User) GetActiveOrgRepositoryIDs(units ...UnitType) ([]int64, error) {
    var ids []int64
    if err := x.Table("repository").
    Cols("repository.id").
    Join("INNER", "team_user", "repository.owner_id = team_user.org_id").
    Join("INNER", "team_repo", "(? != ? and repository.is_private != ?) OR (team_user.team_id = team_repo.team_id AND repository.id = team_repo.repo_id)", true, u.IsRestricted, true).
    Where("team_user.uid = ?", u.ID).
    Where(builder.Eq{"is_archived": false}).
    GroupBy("repository.id").Find(&ids); err != nil {
    return nil, err
    }
    if len(units) > 0 {
    return FilterOutRepoIdsWithoutUnitAccess(u, ids, units...)
    }
    return ids, nil
    }

Since this code path only appears to be used in this pull request page it might be worth making a more specific functions for this query?

@somera
Copy link
Author

somera commented Apr 13, 2021

@nsmith5 the first question is, how the "show pulls" process should be changed?

I see two ways:

  1. First fast fix: get only repos with opened or closed pull requests back -> use the current view
  2. Rebuild the whole process -> has new view

Imagine the user has 1000 or 2000 repos? -> The speed of this view will be much slower.

Collecting all the informations is not the best solution. Show only list with opened pull requests. Than add an option for showing the closed pull requests. And get the information for the selected option after users action. As user is my goal to see first and fast opened pull requests. Cause I will approve or deny them.

Which option you choose depends on your target group.

@somera somera changed the title [Question] Open Pull-Requests view with > 500 organizations need more than 1 minute Open Pull-Requests view with > 500 organizations need more than 1 minute Apr 14, 2021
@zeripath zeripath modified the milestones: 1.14.1, 1.14.2 Apr 15, 2021
@lunny
Copy link
Member

lunny commented Apr 24, 2021

It depends on the machine I think. I tested my local instance (ec69f34) with postgres 9.6 (Macbook pro 13 2020), I created 600 orgs, and it took 1229ms on first org pull requests page and 494ms on second org pull requests page.

@somera Could you try v1.14.1 ?

@somera
Copy link
Author

somera commented Apr 24, 2021

It depends on the machine I think. I tested my local instance (ec69f34) with postgres 9.6 (Macbook pro 13 2020), I created 600 orgs, and it took 1229ms on first org pull requests page and 494ms on second org pull requests page.

@somera Could you try v1.14.1 ?

Have you created empty orgs?

Yes, it will be faster with better hardware. But I would say, that the current flow is not scalable.

At the moment I have:

  • 550 organisations
  • 5461 repos

And there are ZERO pull requests.

Here the result ...

image

@somera
Copy link
Author

somera commented Apr 25, 2021

First call

image

Second call

image

Third call

image

And I'm using PostgreSQL 13 and Memcached.

@lunny
Copy link
Member

lunny commented Jun 7, 2021

@somera Could you test if #16099 could help you?

@somera
Copy link
Author

somera commented Jun 7, 2021

@somera Could you test if #16099 could help you?

I can't test an unreleased Gitea version.

@6543 6543 modified the milestones: 1.14.3, 1.14.4 Jun 10, 2021
@somera
Copy link
Author

somera commented Jun 18, 2021

@lunny tested now with official 1.14.3

image

@zeripath
Copy link
Contributor

It's not backported to 1.14.3

@somera
Copy link
Author

somera commented Aug 22, 2021

@zeripath @lunny as I saw should it work fasten in 1.15.0. Today updated. And ...

Pull-Requests:
image

Issues:
image

The "fix" is not working.

@zeripath zeripath reopened this Aug 24, 2021
@zeripath
Copy link
Contributor

Can you give us some updated logs?

@somera
Copy link
Author

somera commented Aug 24, 2021

Can you give us some updated logs?

Take a look from this timestamp

2021/08/24 22:38:38 ...s/context/context.go:740:1() [D] Session ID: 49a88c0a05f4fe4b
2021/08/24 22:38:38 ...s/context/context.go:741:1() [D] CSRF Token: 4963LSms59-jIJIQYyeyCv4Rs9Y6MTYyOTgzNzQ5MzQ2NTQ0MjcxNQ
2021/08/24 22:39:48 ...s/context/context.go:185:HTML() [D] Template: user/dashboard/issues

See attachment. There are no more logs.

Gitea makes for every repo 2 or 3 queries. I have 5997 repos. ;) Sorry.
xorm.zip

@somera
Copy link
Author

somera commented Aug 24, 2021

To reproduce it just import ~100 mirrors or create repos. Without this you can't analyze it.

@lunny
Copy link
Member

lunny commented Aug 25, 2021

Could you change your configuration file to change log stack level to error? And give a new log file include http and xorm

@somera
Copy link
Author

somera commented Aug 25, 2021

Could you change your configuration file to change log stack level to error? And give a new log file include http and xorm

This is now my configuration:

[log]
MODE             = file,file-servicesmirror
MAX_DAYS         = 15
; LEVEL            = Debug
LEVEL            = Error
ROOT_PATH        = /var/lib/gitea/log
ROUTER           = file
; ROUTER_LOG_LEVEL = Debug
ROUTER_LOG_LEVEL = Error
STACKTRACE_LEVEL = Error
XORM             = file

[log.file.xorm]
FILE_NAME        = xorm.log
; STACKTRACE_LEVEL = Debug
STACKTRACE_LEVEL = Error

[log.file-servicesmirror]
MODE       = file
FILE_NAME  = servicesmirror-trace.log
; LEVEL      = Debug
LEVEL      = Error
EXPRESSION = services/mirror

But there will be nothing logged and the runtime chanched to:

Issues: Powered by Gitea Version: 1.15.0 Seite: 23249ms Template: 34ms

Pulls: Powered by Gitea Version: 1.15.0 Seite: 23240ms Template: 33ms

@lunny why is loggin in Gitea so slow? 23 seconds with loglevel=error and ~70 seconds with loglevel=debug.

@lunny
Copy link
Member

lunny commented Aug 25, 2021

You have to change [database] LOG_SQL=true

@somera
Copy link
Author

somera commented Aug 25, 2021

You have to change [database] LOG_SQL=true

Yes. This looks so:

[database]
DB_TYPE  = postgres
CHARSET  = utf8
LOG_SQL  = true

[log]
MODE             = file,file-servicesmirror
MAX_DAYS         = 15
LEVEL            = Error
ROOT_PATH        = /var/lib/gitea/log
ROUTER           = file
ROUTER_LOG_LEVEL = Error
STACKTRACE_LEVEL = Error
XORM             = file

[log.file.xorm]
FILE_NAME        = xorm.log
STACKTRACE_LEVEL = Error

[log.file-servicesmirror]
MODE       = file
FILE_NAME  = servicesmirror-trace.log
LEVEL      = Error
EXPRESSION = services/mirror

But sql queries are not logged. The queries can you see here: #15412 (comment)

@zeripath
Copy link
Contributor

You have to change [database] LOG_SQL=true

Yes. This looks so:

[database]
DB_TYPE  = postgres
CHARSET  = utf8
LOG_SQL  = true

[log]
MODE             = file,file-servicesmirror
MAX_DAYS         = 15
LEVEL            = Error
ROOT_PATH        = /var/lib/gitea/log
ROUTER           = file
ROUTER_LOG_LEVEL = Error
STACKTRACE_LEVEL = Error
XORM             = file

[log.file.xorm]
FILE_NAME        = xorm.log
STACKTRACE_LEVEL = Error

[log.file-servicesmirror]
MODE       = file
FILE_NAME  = servicesmirror-trace.log
LEVEL      = Error
EXPRESSION = services/mirror

But sql queries are not logged. The queries can you see here: #15412 (comment)

You need to re-read the logging documentation https://docs.gitea.io/en-us/logging-configuration/#debugging-problems.

Some points:

  • Please, just set STACKTRACE_LEVEL = none it's not helpful except in very very rare levels.
  • Please, if it is at all possible, when sending us logs, send all of your logs to the console as it is the simplest way to get them all together and nicely interleaved.
  • Setting the LEVEL=error for everything including the xorm logger is the reason you're not seeing any SQL logs.
  • In this case SQL logs will be helpful

So, this is what your logging configuration should look like:

[database]
...
LOG_SQL = true ; Normally we want this to be false but I'm explicitly asking you to set this to true

[log]
MODE=console ; PLEASE JUST SEND EVERYTHING TO THE CONSOLE AND REDIRECT FROM THERE
LEVEL=debug
ROUTER = console
REDIRECT_MACARON_LOG=true
COLORIZE=false

That's it nothing else should be necessary - drop the rest of the [log.xxx] sections. Don't set STACKTRACE_LEVEL. Don't set XORM, don't set ROUTER_LOG_LEVEL.

Just that. If you still don't see XORM logs you can set XORM=, or XORM=console but the default should be XORM=, and MODE=console should mean that they appear on the console.

If you absolutely cannot send things to the console and send us logs from back from there then:

[database]
...
LOG_SQL = true 

[log]
;ROOT_PATH= ; set this to what you need it to be
MODE=file
LEVEL=debug
ROUTER=file
XORM=file
REDIRECT_MACARON_LOG=true
COLORIZE=false

but please try to give us the consolidated console logs as it is so much easier for us.

@somera
Copy link
Author

somera commented Aug 26, 2021

Sorry, can't set it to console. I used the last part

[database]
...
LOG_SQL = true 

[log]
;ROOT_PATH= ; set this to what you need it to be
MODE=file
LEVEL=debug
ROUTER=file
XORM=file
REDIRECT_MACARON_LOG=true
COLORIZE=false

Logs are attached. Gitea start -> open pull requests -> Gitea stop

gitea_log.tar.gz

It will be easier if you add 100-200 mirrors on your instance. So you can better reproduce it. You don't need 5000 repos.

@lunny
Copy link
Member

lunny commented Aug 26, 2021

Every repo have three database queries. They are repeated about 6000 times.

2021/08/26 14:35:20 models/user.go:1370:getUserByID() [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 [21] - 605.32µs
2021/08/26 14:35:20 models/repo_unit.go:210:getUnitsByRepoID() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) [69] - 435.406µs
2021/08/26 14:35:20 models/repo.go:1688:getRepositoryByID() [I] [SQL] SELECT "id", "owner_id", "owner_name", "lower_name", "name", "description", "website", "original_service_type", "original_url", "default_branch", "num_watches", "num_stars", "num_forks", "num_issues", "num_closed_issues", "num_pulls", "num_closed_pulls", "num_milestones", "num_closed_milestones", "num_projects", "num_closed_projects", "is_private", "is_empty", "is_archived", "is_mirror", "status", "is_fork", "fork_id", "is_template", "template_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "trust_model", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE "id"=$1 LIMIT 1 [70] - 640.092µs
2021/08/26 14:35:20 ...rm.io/xorm/engine.go:1214:Get() [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 [70 1] - 486.756µs

@somera
Copy link
Author

somera commented Aug 26, 2021

Every repo have three database queries. They are repeated about 6000 times.

2021/08/26 14:35:20 models/user.go:1370:getUserByID() [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 [21] - 605.32µs
2021/08/26 14:35:20 models/repo_unit.go:210:getUnitsByRepoID() [I] [SQL] SELECT "id", "repo_id", "type", "config", "created_unix" FROM "repo_unit" WHERE (repo_id = $1) [69] - 435.406µs
2021/08/26 14:35:20 models/repo.go:1688:getRepositoryByID() [I] [SQL] SELECT "id", "owner_id", "owner_name", "lower_name", "name", "description", "website", "original_service_type", "original_url", "default_branch", "num_watches", "num_stars", "num_forks", "num_issues", "num_closed_issues", "num_pulls", "num_closed_pulls", "num_milestones", "num_closed_milestones", "num_projects", "num_closed_projects", "is_private", "is_empty", "is_archived", "is_mirror", "status", "is_fork", "fork_id", "is_template", "template_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "trust_model", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE "id"=$1 LIMIT 1 [70] - 640.092µs
2021/08/26 14:35:20 ...rm.io/xorm/engine.go:1214:Get() [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 [70 1] - 486.756µs

I know. This is what I wrote here #15412 (comment) (see the attached log).

@lunny
Copy link
Member

lunny commented Aug 26, 2021

So all the 6000 repos in one org?

@somera
Copy link
Author

somera commented Aug 26, 2021

So all the 6000 repos in one org?

Current stats:

Orgs: 642
Repos: 6000

@zeripath
Copy link
Contributor

These calls are all occuring in:

showReposMap, err := repoIDMap(ctxUser, issueCountByRepo, unitType)

this does:

func repoIDMap(ctxUser *models.User, issueCountByRepo map[int64]int64, unitType models.UnitType) (map[int64]*models.Repository, error) {
repoByID := make(map[int64]*models.Repository, len(issueCountByRepo))
for id := range issueCountByRepo {
if id <= 0 {
continue
}
if _, ok := repoByID[id]; !ok {
repo, err := models.GetRepositoryByID(id)
if models.IsErrRepoNotExist(err) {
return nil, err
} else if err != nil {
return nil, fmt.Errorf("GetRepositoryByID: [%d]%v", id, err)
}
repoByID[id] = repo
}
repo := repoByID[id]
// Check if user has access to given repository.
perm, err := models.GetUserRepoPermission(repo, ctxUser)
if err != nil {
return nil, fmt.Errorf("GetUserRepoPermission: [%d]%v", id, err)
}
if !perm.CanRead(unitType) {
log.Debug("User created Issues in Repository which they no longer have access to: [%d]", id)
}
}
return repoByID, nil
}

The issueCountByRepo is filled:

issueCountByRepo, err = models.CountIssuesByRepo(opts)

This is a regression from #13220

@somera
Copy link
Author

somera commented Aug 26, 2021

These calls are all occuring in:

showReposMap, err := repoIDMap(ctxUser, issueCountByRepo, unitType)

this does:

func repoIDMap(ctxUser *models.User, issueCountByRepo map[int64]int64, unitType models.UnitType) (map[int64]*models.Repository, error) {
repoByID := make(map[int64]*models.Repository, len(issueCountByRepo))
for id := range issueCountByRepo {
if id <= 0 {
continue
}
if _, ok := repoByID[id]; !ok {
repo, err := models.GetRepositoryByID(id)
if models.IsErrRepoNotExist(err) {
return nil, err
} else if err != nil {
return nil, fmt.Errorf("GetRepositoryByID: [%d]%v", id, err)
}
repoByID[id] = repo
}
repo := repoByID[id]
// Check if user has access to given repository.
perm, err := models.GetUserRepoPermission(repo, ctxUser)
if err != nil {
return nil, fmt.Errorf("GetUserRepoPermission: [%d]%v", id, err)
}
if !perm.CanRead(unitType) {
log.Debug("User created Issues in Repository which they no longer have access to: [%d]", id)
}
}
return repoByID, nil
}

The issueCountByRepo is filled:

issueCountByRepo, err = models.CountIssuesByRepo(opts)

This is a regression from #13220

This is

image

the first problem in this process.

The first query should return all the repos which have issues (issue table has repo_id) or pull requests (pull_request table hast base_repo_id). And than you have a list of possible repos (in my case 0) to get all the needed data. But this should be optimized to.

And for my 6000 repos there are NULL issues and NULL pull requests. In this case gitea should show "empty" page in less than 1-2 seconds.

@zeripath
Copy link
Contributor

@somera if you can compile gitea - if you say that these counts are all 0, then a simple solution may be to change:

 	repoByID := make(map[int64]*models.Repository, len(issueCountByRepo)) 
 	for id := range issueCountByRepo { 
 		if id <= 0 { 
 			continue 
 		} 

to

 	repoByID := make(map[int64]*models.Repository, len(issueCountByRepo)) 
 	for id, count := range issueCountByRepo { 
 		if id <= 0 || count == 0 { 
 			continue 
 		} 

but I'm not certain.

The whole code needs to be rewritten as it's clearly brutally inefficient.

@somera
Copy link
Author

somera commented Aug 26, 2021

@zeripath I can work with the current release. I'm not using this feature at the moment. But if, gitea wasn't usable for me in normal process with this workflow.

@lunny
Copy link
Member

lunny commented Aug 27, 2021

@somera Could you help to try #16839 ?

@somera
Copy link
Author

somera commented Aug 27, 2021

@somera Could you help to try #16839 ?

I can. But if I do this, than my current system will be upgraded? Yes? I'm running 1.15.0 now.

But tell me please what should I do. I don't developing with go. ;)

What should I checkout?
How to compile?

@zeripath zeripath modified the milestones: 1.14.4, 1.16.0 Aug 29, 2021
@somera
Copy link
Author

somera commented Aug 31, 2021

@somera Could you help to try #16839 ?

I try to setup a new test system for this. I can't test it on my 24/7 system.

@somera
Copy link
Author

somera commented Jan 31, 2022

Looks in 1.16.0 good now

image

Thx!

@go-gitea go-gitea locked and limited conversation to collaborators Apr 28, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
performance/speed performance issues with slow downs type/bug
Projects
None yet
5 participants