Extremely slow post-receive hook of Gitea - in Docker on a Synology server #13706

obermeim · 2020-11-26T18:03:53Z

Gitea version (or commit ref): 1.11.4
Git version: git version 2.24.1
Operating system: Docker on Synology NAS
Database (use [x]):
- PostgreSQL
- MySQL
- MSSQL
- SQLite
Can you reproduce the bug at https://try.gitea.io:
- Yes (provide example URL)
- No
- Not relevant
Log gist:

Description

Hello,

if I push to my repository it takes up to 30-40 seconds. Looking at the logs I see one line that has raised my attention:

[Macaron] 2020-11-26 17:55:24: Completed POST /api/internal/hook/post-receive/StormTest/newFramework3 200 OK in 19.555562956s

Why does the post-receive hook take 20 seconds to complete for a repository with a size of only about 2MB?
I have not setup any post-receive hook. What is going wrong?

Any ideas? Help appreciated.

Kind regards,
Markus

Logs

Server listening on 0.0.0.0 port 22.
2020/11/26 17:52:25 cmd/web.go:107:runWeb() [I] Starting Gitea on PID: 17
2020/11/26 17:52:26 ...dules/setting/git.go:91:newGit() [I] Git Version: 2.24.1, Wire Protocol Version 2 Enabled
2020/11/26 17:52:26 routers/init.go:87:GlobalInit() [T] AppPath: /app/gitea/gitea
2020/11/26 17:52:26 routers/init.go:88:GlobalInit() [T] AppWorkPath: /app/gitea
2020/11/26 17:52:26 routers/init.go:89:GlobalInit() [T] Custom path: /data/gitea
2020/11/26 17:52:26 routers/init.go:90:GlobalInit() [T] Log path: /data/gitea/log
[Macaron] 2020-11-26 17:54:27: Started GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:54:31: Completed GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack 200 OK in 3.466846358s
[Macaron] 2020-11-26 17:54:31: Started POST /StormTest/newFramework3.git/git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:54:35: Completed POST /StormTest/newFramework3.git/git-upload-pack 200 OK in 3.641073732s
[Macaron] 2020-11-26 17:54:52: Started GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack for 172.26.0.1
[Macaron] 2020-11-26 17:54:53: Completed GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack 401 Unauthorized in 253.691108ms
[Macaron] 2020-11-26 17:54:53: Started GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack for 172.26.0.1
[Macaron] 2020-11-26 17:54:54: Completed GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack 200 OK in 1.470739886s
[Macaron] 2020-11-26 17:54:54: Started POST /StormTest/newFramework3.git/git-receive-pack for 172.26.0.1
[Macaron] 2020-11-26 17:54:59: Started POST /api/internal/hook/pre-receive/StormTest/newFramework3 for 127.0.0.1
[Macaron] 2020-11-26 17:54:59: Completed POST /api/internal/hook/pre-receive/StormTest/newFramework3 200 OK in 90.02641ms
[Macaron] 2020-11-26 17:55:04: Started POST /api/internal/hook/post-receive/StormTest/newFramework3 for 127.0.0.1
[Macaron] 2020-11-26 17:55:13: Started GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:55:14: Completed GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack 200 OK in 630.446413ms
[Macaron] 2020-11-26 17:55:14: Started POST /StormTest/newFramework3.git/git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:55:14: Completed POST /StormTest/newFramework3.git/git-upload-pack 200 OK in 288.453021ms
[Macaron] 2020-11-26 17:55:14: Started GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:55:16: Completed GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack 200 OK in 1.706482304s
[Macaron] 2020-11-26 17:55:16: Started POST /StormTest/newFramework3.git/git-upload-pack for 172.26.0.1
[Macaron] 2020-11-26 17:55:16: Completed POST /StormTest/newFramework3.git/git-upload-pack 200 OK in 112.871945ms
[Macaron] 2020-11-26 17:55:24: Completed POST /api/internal/hook/post-receive/StormTest/newFramework3 200 OK in 19.555562956s
[Macaron] 2020-11-26 17:55:24: Completed POST /StormTest/newFramework3.git/git-receive-pack 200 OK in 29.387418352s

The text was updated successfully, but these errors were encountered:

techknowlogick · 2020-11-26T18:14:14Z

There has been a lot of work on speed, and other performance increases. Please update to at least the latest version.

obermeim · 2020-11-26T23:01:21Z

Hi @techknowlogick ,

I have installed version 1.12.6 but actually if you look at the logs below there is no change.

Any ideas?

Server listening on 0.0.0.0 port 22.
2020/11/26 22:33:46 cmd/web.go:107:runWeb() [I] Starting Gitea on PID: 16
2020/11/26 22:33:46 ...dules/setting/git.go:93:newGit() [I] Git Version: 2.24.3, Wire Protocol Version 2 Enabled
2020/11/26 22:33:46 routers/init.go:118:GlobalInit() [T] AppPath: /app/gitea/gitea
2020/11/26 22:33:46 routers/init.go:119:GlobalInit() [T] AppWorkPath: /app/gitea
2020/11/26 22:33:46 routers/init.go:120:GlobalInit() [T] Custom path: /data/gitea
2020/11/26 22:33:46 routers/init.go:121:GlobalInit() [T] Log path: /data/gitea/log
[Macaron] 2020-11-26 22:56:45: Started GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack for 172.28.0.1
[Macaron] 2020-11-26 22:56:45: Completed GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack 401 Unauthorized in 80.451647ms
[Macaron] 2020-11-26 22:56:45: Started GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack for 172.28.0.1
[Macaron] 2020-11-26 22:56:47: Completed GET /StormTest/newFramework3.git/info/refs?service=git-receive-pack 200 OK in 1.475143321s
[Macaron] 2020-11-26 22:56:47: Started POST /StormTest/newFramework3.git/git-receive-pack for 172.28.0.1
[Macaron] 2020-11-26 22:56:50: Started POST /api/internal/hook/pre-receive/StormTest/newFramework3 for 127.0.0.1
[Macaron] 2020-11-26 22:56:50: Completed POST /api/internal/hook/pre-receive/StormTest/newFramework3 200 OK in 25.004235ms
[Macaron] 2020-11-26 22:56:52: Started POST /api/internal/hook/post-receive/StormTest/newFramework3 for 127.0.0.1
[Macaron] 2020-11-26 22:56:59: Started GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack for 172.28.0.1
[Macaron] 2020-11-26 22:57:01: Started GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack for 172.28.0.1
[Macaron] 2020-11-26 22:57:02: Completed GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack 200 OK in 2.769898255s
[Macaron] 2020-11-26 22:57:02: Started POST /StormTest/newFramework3.git/git-upload-pack for 172.28.0.1
[Macaron] 2020-11-26 22:57:02: Completed GET /StormTest/newFramework3.git/info/refs?service=git-upload-pack 200 OK in 1.260594155s
[Macaron] 2020-11-26 22:57:03: Started POST /StormTest/newFramework3.git/git-upload-pack for 172.28.0.1
[Macaron] 2020-11-26 22:57:04: Completed POST /StormTest/newFramework3.git/git-upload-pack 200 OK in 2.696850443s
[Macaron] 2020-11-26 22:57:06: Completed POST /StormTest/newFramework3.git/git-upload-pack 200 OK in 3.516476785s
[Macaron] 2020-11-26 22:57:12: Completed POST /api/internal/hook/post-receive/StormTest/newFramework3 200 OK in 19.45077729s
[Macaron] 2020-11-26 22:57:12: Completed POST /StormTest/newFramework3.git/git-receive-pack 200 OK in 24.916792616s

zeripath · 2020-11-27T10:07:35Z

OK so the post-receive endpoint here is doing:

gitea/routers/private/hook.go

Lines 373 to 529 in b7ad2d4

    
           // HookPostReceive updates services and users 
        
           func HookPostReceive(ctx *macaron.Context, opts private.HookOptions) { 
        
           	ownerName := ctx.Params(":owner") 
        
           	repoName := ctx.Params(":repo") 
        
           	var repo *models.Repository 
        
           	updates := make([]*repofiles.PushUpdateOptions, 0, len(opts.OldCommitIDs)) 
        
           	wasEmpty := false 
        
           	for i := range opts.OldCommitIDs { 
        
           		refFullName := opts.RefFullNames[i] 
        
           		// Only trigger activity updates for changes to branches or 
        
           		// tags.  Updates to other refs (eg, refs/notes, refs/changes, 
        
           		// or other less-standard refs spaces are ignored since there 
        
           		// may be a very large number of them). 
        
           		if strings.HasPrefix(refFullName, git.BranchPrefix) || strings.HasPrefix(refFullName, git.TagPrefix) { 
        
           			if repo == nil { 
        
           				var err error 
        
           				repo, err = models.GetRepositoryByOwnerAndName(ownerName, repoName) 
        
           				if err != nil { 
        
           					log.Error("Failed to get repository: %s/%s Error: %v", ownerName, repoName, err) 
        
           					ctx.JSON(http.StatusInternalServerError, private.HookPostReceiveResult{ 
        
           						Err: fmt.Sprintf("Failed to get repository: %s/%s Error: %v", ownerName, repoName, err), 
        
           					}) 
        
           					return 
        
           				} 
        
           				if repo.OwnerName == "" { 
        
           					repo.OwnerName = ownerName 
        
           				} 
        
           				wasEmpty = repo.IsEmpty 
        
           			} 
        
           			option := repofiles.PushUpdateOptions{ 
        
           				RefFullName:  refFullName, 
        
           				OldCommitID:  opts.OldCommitIDs[i], 
        
           				NewCommitID:  opts.NewCommitIDs[i], 
        
           				PusherID:     opts.UserID, 
        
           				PusherName:   opts.UserName, 
        
           				RepoUserName: ownerName, 
        
           				RepoName:     repoName, 
        
           			} 
        
           			updates = append(updates, &option) 
        
           			if repo.IsEmpty && option.IsBranch() && option.BranchName() == "master" { 
        
           				// put the master branch first 
        
           				copy(updates[1:], updates) 
        
           				updates[0] = &option 
        
           			} 
        
           		} 
        
           	} 
        
           	if repo != nil && len(updates) > 0 { 
        
           		if err := repofiles.PushUpdates(repo, updates); err != nil { 
        
           			log.Error("Failed to Update: %s/%s Total Updates: %d", ownerName, repoName, len(updates)) 
        
           			for i, update := range updates { 
        
           				log.Error("Failed to Update: %s/%s Update: %d/%d: Branch: %s", ownerName, repoName, i, len(updates), update.BranchName()) 
        
           			} 
        
           			log.Error("Failed to Update: %s/%s Error: %v", ownerName, repoName, err) 
        
           			ctx.JSON(http.StatusInternalServerError, private.HookPostReceiveResult{ 
        
           				Err: fmt.Sprintf("Failed to Update: %s/%s Error: %v", ownerName, repoName, err), 
        
           			}) 
        
           			return 
        
           		} 
        
           	} 
        
           	results := make([]private.HookPostReceiveBranchResult, 0, len(opts.OldCommitIDs)) 
        
           	// We have to reload the repo in case its state is changed above 
        
           	repo = nil 
        
           	var baseRepo *models.Repository 
        
           	for i := range opts.OldCommitIDs { 
        
           		refFullName := opts.RefFullNames[i] 
        
           		newCommitID := opts.NewCommitIDs[i] 
        
           		branch := git.RefEndName(opts.RefFullNames[i]) 
        
           		if newCommitID != git.EmptySHA && strings.HasPrefix(refFullName, git.BranchPrefix) { 
        
           			if repo == nil { 
        
           				var err error 
        
           				repo, err = models.GetRepositoryByOwnerAndName(ownerName, repoName) 
        
           				if err != nil { 
        
           					log.Error("Failed to get repository: %s/%s Error: %v", ownerName, repoName, err) 
        
           					ctx.JSON(http.StatusInternalServerError, private.HookPostReceiveResult{ 
        
           						Err:          fmt.Sprintf("Failed to get repository: %s/%s Error: %v", ownerName, repoName, err), 
        
           						RepoWasEmpty: wasEmpty, 
        
           					}) 
        
           					return 
        
           				} 
        
           				if repo.OwnerName == "" { 
        
           					repo.OwnerName = ownerName 
        
           				} 
        
           				if !repo.AllowsPulls() { 
        
           					// We can stop there's no need to go any further 
        
           					ctx.JSON(http.StatusOK, private.HookPostReceiveResult{ 
        
           						RepoWasEmpty: wasEmpty, 
        
           					}) 
        
           					return 
        
           				} 
        
           				baseRepo = repo 
        
           				if repo.IsFork { 
        
           					if err := repo.GetBaseRepo(); err != nil { 
        
           						log.Error("Failed to get Base Repository of Forked repository: %-v Error: %v", repo, err) 
        
           						ctx.JSON(http.StatusInternalServerError, private.HookPostReceiveResult{ 
        
           							Err:          fmt.Sprintf("Failed to get Base Repository of Forked repository: %-v Error: %v", repo, err), 
        
           							RepoWasEmpty: wasEmpty, 
        
           						}) 
        
           						return 
        
           					} 
        
           					baseRepo = repo.BaseRepo 
        
           				} 
        
           			} 
        
           			if !repo.IsFork && branch == baseRepo.DefaultBranch { 
        
           				results = append(results, private.HookPostReceiveBranchResult{}) 
        
           				continue 
        
           			} 
        
           			pr, err := models.GetUnmergedPullRequest(repo.ID, baseRepo.ID, branch, baseRepo.DefaultBranch) 
        
           			if err != nil && !models.IsErrPullRequestNotExist(err) { 
        
           				log.Error("Failed to get active PR in: %-v Branch: %s to: %-v Branch: %s Error: %v", repo, branch, baseRepo, baseRepo.DefaultBranch, err) 
        
           				ctx.JSON(http.StatusInternalServerError, private.HookPostReceiveResult{ 
        
           					Err: fmt.Sprintf( 
        
           						"Failed to get active PR in: %-v Branch: %s to: %-v Branch: %s Error: %v", repo, branch, baseRepo, baseRepo.DefaultBranch, err), 
        
           					RepoWasEmpty: wasEmpty, 
        
           				}) 
        
           				return 
        
           			} 
        
           			if pr == nil { 
        
           				if repo.IsFork { 
        
           					branch = fmt.Sprintf("%s:%s", repo.OwnerName, branch) 
        
           				} 
        
           				results = append(results, private.HookPostReceiveBranchResult{ 
        
           					Message: setting.Git.PullRequestPushMessage && repo.AllowsPulls(), 
        
           					Create:  true, 
        
           					Branch:  branch, 
        
           					URL:     fmt.Sprintf("%s/compare/%s...%s", baseRepo.HTMLURL(), util.PathEscapeSegments(baseRepo.DefaultBranch), util.PathEscapeSegments(branch)), 
        
           				}) 
        
           			} else { 
        
           				results = append(results, private.HookPostReceiveBranchResult{ 
        
           					Message: setting.Git.PullRequestPushMessage && repo.AllowsPulls(), 
        
           					Create:  false, 
        
           					Branch:  branch, 
        
           					URL:     fmt.Sprintf("%s/pulls/%d", baseRepo.HTMLURL(), pr.Index), 
        
           				}) 
        
           			} 
        
           		} 
        
           	} 
        
           	ctx.JSON(http.StatusOK, private.HookPostReceiveResult{ 
        
           		Results:      results, 
        
           		RepoWasEmpty: wasEmpty, 
        
           	}) 
        
           }

This essentially iterates through the stdin of post-receive checking and updating the refs that the push has updated collates them and then:

gitea/routers/private/hook.go

Line 425 in b7ad2d4

if err := repofiles.PushUpdates(repo, updates); err != nil {

gitea/modules/repofiles/update.go

Lines 639 to 700 in b7ad2d4

    
           // PushUpdates generates push action history feeds for push updating multiple refs 
        
           func PushUpdates(repo *models.Repository, optsList []*PushUpdateOptions) error { 
        
           	repoPath := repo.RepoPath() 
        
           	_, err := git.NewCommand("update-server-info").RunInDir(repoPath) 
        
           	if err != nil { 
        
           		return fmt.Errorf("Failed to call 'git update-server-info': %v", err) 
        
           	} 
        
           	gitRepo, err := git.OpenRepository(repoPath) 
        
           	if err != nil { 
        
           		return fmt.Errorf("OpenRepository: %v", err) 
        
           	} 
        
           	defer gitRepo.Close() 
        
           	if err = repo.UpdateSize(models.DefaultDBContext()); err != nil { 
        
           		log.Error("Failed to update size for repository: %v", err) 
        
           	} 
        
           	actions, err := createCommitRepoActions(repo, gitRepo, optsList) 
        
           	if err != nil { 
        
           		return err 
        
           	} 
        
           	if err := CommitRepoAction(actions...); err != nil { 
        
           		return fmt.Errorf("CommitRepoAction: %v", err) 
        
           	} 
        
           	var pusher *models.User 
        
           	for _, opts := range optsList { 
        
           		if !opts.IsBranch() { 
        
           			continue 
        
           		} 
        
           		branch := opts.BranchName() 
        
           		if pusher == nil || pusher.ID != opts.PusherID { 
        
           			var err error 
        
           			pusher, err = models.GetUserByID(opts.PusherID) 
        
           			if err != nil { 
        
           				return err 
        
           			} 
        
           		} 
        
           		if !opts.IsDelRef() { 
        
           			if err = models.RemoveDeletedBranch(repo.ID, branch); err != nil { 
        
           				log.Error("models.RemoveDeletedBranch %s/%s failed: %v", repo.ID, branch, err) 
        
           			} 
        
           			if err = models.WatchIfAuto(opts.PusherID, repo.ID, true); err != nil { 
        
           				log.Warn("Fail to perform auto watch on user %v for repo %v: %v", opts.PusherID, repo.ID, err) 
        
           			} 
        
           			log.Trace("TriggerTask '%s/%s' by %s", repo.Name, branch, pusher.Name) 
        
           			go pull_service.AddTestPullRequestTask(pusher, repo.ID, branch, true, opts.OldCommitID, opts.NewCommitID) 
        
           			// close all related pulls 
        
           		} else if err = pull_service.CloseBranchPulls(pusher, repo.ID, branch); err != nil { 
        
           			log.Error("close related pull request failed: %v", err) 
        
           		} 
        
           	} 
        
           	return nil 
        
           }

L642 is unlikely to be slow here.

However L652 could be the problem:

gitea/modules/repofiles/update.go

Line 652 in b7ad2d4

if err = repo.UpdateSize(models.DefaultDBContext()); err != nil {

How big is your repository?

obermeim · 2020-11-27T10:20:07Z

Hi @zeripath ,

my repository is I think very small about 2MB.

But I am using SQlite. My doubt was the performance of the database but I do not know if this could be related?

zeripath · 2020-11-27T10:28:15Z

Only 2Mb? There's something very wrong going on here.

obermeim · 2020-11-27T10:45:16Z

Is there any way I can help debugging?

zeripath · 2020-11-27T10:49:36Z

We need more logs. Read: https://docs.gitea.io/en-us/logging-configuration/#debugging-problems

In addition, consider setting:

[server]
ENABLE_PPROF = true

The way you use pprof is on the server do:

go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60

top

should give you the longest running functions. web would produce an svg. list <functionname> should give you a line-by-line analysis if the source is available.

SQL logs could be obtained using:

[database]
LOG_SQL=true
...

Additional git logs using:

RUN_MODE = dev

However the pprof option and the additional logs from following the debugging information above should help.

miou-gh · 2021-02-10T19:32:45Z

I'm using the latest version and sometimes it takes several seconds to push files to a repository, all of these files range from 1 KB to 800 KB. I'm using the API from the automatically generated client library from https://github.com/belidzs/Gitea and automating a process of uploading thousands of small files to thousands of repositories belonging to thousands of users.

[git-module] C:\Users\Tilly\Desktop\Gitea\data\tmp\local-repo\upload.git166757579: C:\Program Files\Git\cmd\git.exe -c credential.helper= -c protocol.version=2 -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= cat-file --batch
2021/02/10 14:11:32 Completed POST /api/v1/repos/quillanio/PW5zoj8JwRbUI/contents/PW5zoj8JwRbUI.2021.tson 422 Unprocessable Entity in 1.2157502s
2021/02/10 14:11:32 Completed POST /api/v1/admin/users/aditgrwuht/repos 409 Conflict in 550.5283ms
2021/02/10 14:11:32 Completed POST /api/v1/admin/users/encrypted47/repos 409 Conflict in 559.5039ms
[git-module] C:\Users\Tilly\Desktop\Gitea\data\tmp\local-repo\upload.git166757579: C:\Program Files\Git\cmd\git.exe -c credential.helper= -c protocol.version=2 -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= ls-tree d311f9ebfd89a7159a2ffb46b23fdeb7c3038f7b
2021/02/10 14:11:32 Completed POST /api/v1/admin/users/andre12345olen/repos 409 Conflict in 586.432ms
2021/02/10 14:11:32 Completed POST /api/v1/repos/guidosreis/PWW5u9FzJbbkI/contents/PWW5u9FzJbbkI.2014.tson 201 Created in 6.8387158s
[git-module] stdout:
100644 blob 85fdccfdaf86e71eed2424d625e4caac1124384a	PWkfZ8FKY3bEI.2021.tson
100644 blob a7b56e7676ebe2f70f8f2562c0c91764340c606a	README.md

zeripath · 2021-02-10T20:22:27Z

what do you mean by I'm using the latest version 1.13.1? master? which commit?

miou-gh · 2021-02-10T22:04:19Z

what do you mean by I'm using the latest version 1.13.1? master? which commit?

Yes, 1.13.1.

zeripath · 2021-02-10T22:54:40Z

Ok could you read #13706 (comment) so that we actually have some information to go about debugging this

miou-gh · 2021-02-11T01:55:16Z

Ok could you read #13706 (comment) so that we actually have some information to go about debugging this

I have attached the trace log file here:
log.txt

(pprof) top
Showing nodes accounting for 26.12s, 90.44% of 28.88s total
Dropped 564 nodes (cum <= 0.14s)
Showing top 10 nodes out of 68
      flat  flat%   sum%        cum   cum%
    13.68s 47.37% 47.37%     13.68s 47.37%  golang.org/x/crypto/argon2.blamkaSSE4
     5.77s 19.98% 67.35%      5.77s 19.98%  golang.org/x/crypto/argon2.mixBlocksSSE2
     2.30s  7.96% 75.31%      2.30s  7.96%  golang.org/x/crypto/argon2.xorBlocksSSE2
     1.46s  5.06% 80.37%      3.10s 10.73%  runtime.scanobject
     0.76s  2.63% 83.00%      0.76s  2.63%  runtime.memclrNoHeapPointers
     0.72s  2.49% 85.49%      0.84s  2.91%  runtime.findObject
     0.66s  2.29% 87.78%      0.66s  2.29%  runtime.duffzero
     0.30s  1.04% 88.82%      0.31s  1.07%  runtime.cgocall
     0.26s   0.9% 89.72%      0.27s  0.93%  runtime.pageIndexOf (inline)
     0.21s  0.73% 90.44%      0.21s  0.73%  golang.org/x/crypto/argon2.phi

techknowlogick · 2021-02-11T03:54:47Z

@atillabyte thank you. Looks like most of the time is spent on argon2. Please follow #13718 for more details.

miou-gh · 2021-02-11T06:30:41Z

@atillabyte thank you. Looks like most of the time is spent on argon2. Please follow #13718 for more details.

I modified it to use PBKDF2 with 1 iteration so basically instant user creation, now it is this:
I assume it's probably just spawning a new Git process every time is where it spends most of the time. /shrug

(pprof) top
Showing nodes accounting for 1770ms, 57.28% of 3090ms total
Dropped 304 nodes (cum <= 15.45ms)
Showing top 10 nodes out of 409
      flat  flat%   sum%        cum   cum%
     910ms 29.45% 29.45%      910ms 29.45%  runtime.cgocall
     240ms  7.77% 37.22%      250ms  8.09%  syscall.Syscall
     120ms  3.88% 41.10%      120ms  3.88%  syscall.Syscall6
     100ms  3.24% 44.34%      100ms  3.24%  runtime.usleep
      90ms  2.91% 47.25%      160ms  5.18%  runtime.scanobject
      80ms  2.59% 49.84%       80ms  2.59%  runtime.rtsigprocmask
      70ms  2.27% 52.10%       70ms  2.27%  runtime.futex
      60ms  1.94% 54.05%       60ms  1.94%  runtime.(*itabTableType).find
      50ms  1.62% 55.66%       50ms  1.62%  runtime.epollwait
      50ms  1.62% 57.28%       50ms  1.62%  runtime.heapBitsSetType

zeripath · 2021-02-11T06:59:07Z

Web or SVG or one of the other visual tools would be helpful because too doesn't tell us what is calling those functions. A lot of the git calls will end up having to be done though so there might not be further improvement.

At the end of the day reducing from 13s to 910ms should represent a huge improvement though.

miou-gh · 2021-02-11T23:12:20Z

Web or SVG or one of the other visual tools would be helpful because too doesn't tell us what is calling those functions. A lot of the git calls will end up having to be done though so there might not be further improvement.

At the end of the day reducing from 13s to 910ms should represent a huge improvement though.

I have no idea how to do that. I've never used Go prior to this week. Is there a chance there could be benchmarks made?

The improvement doesn't have anything to do with uploading a file into a repository, it's just eliminating the time it takes to compute a hash for a new users password. The upload process for a file that is less than a megabyte in size should take only a few milliseconds, especially when it is being run on localhost.

I'm trying to figure out where that time is being spent, but I'm at a dead end now. To compute the hash for the file in Git shouldn't take very long since it uses SHA-1... any ideas?

zeripath · 2021-02-12T00:06:24Z

They're just commands on the pprof prompt

miou-gh · 2021-02-12T02:33:39Z

SVG is in here:
pprof001.zip

File: gitea
Build ID: fa9c0c71071d5d2faed3ce3af3c0f6102605f81c
Type: cpu
Time: Feb 11, 2021 at 9:26pm (EST)
Duration: 4mins, Total samples = 15.03s ( 6.26%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 8400ms, 55.89% of 15030ms total
Dropped 695 nodes (cum <= 75.15ms)
Showing top 10 nodes out of 437
      flat  flat%   sum%        cum   cum%
    4480ms 29.81% 29.81%     4610ms 30.67%  runtime.cgocall
    1340ms  8.92% 38.72%     1390ms  9.25%  syscall.Syscall
     470ms  3.13% 41.85%      490ms  3.26%  syscall.Syscall6
     340ms  2.26% 44.11%      340ms  2.26%  runtime.epollwait
     330ms  2.20% 46.31%     1260ms  8.38%  runtime.mallocgc
     330ms  2.20% 48.50%      770ms  5.12%  runtime.scanobject
     320ms  2.13% 50.63%      320ms  2.13%  runtime.rtsigprocmask
     280ms  1.86% 52.50%      280ms  1.86%  runtime.usleep
     260ms  1.73% 54.22%      260ms  1.73%  runtime.nextFreeFast (inline)
     250ms  1.66% 55.89%      250ms  1.66%  runtime.epollctl

zeripath · 2021-02-12T03:46:42Z

Ok. Well that's not completely helpful because it's telling me about multiple different http requests. All of these requests appear a little slow to me but none of them match with a slow post-receive which is what this issue was about.

There's a 1.64s call to repo.CreateFile in there which could match with your description of uploading a file - but that is not what this issue is about and if that's where your problem is then you're on the wrong issue.

Now... That doesn't mean to say that we can't help further but please could you be a lot clearer in future.

Ok assuming you actually do want to complain about uploading a file over the API. We need to focus in on that request to figure out where that 1.64s is being spent.

In pprof:

list repo.CreateFile

Should then give us an annotated source code which would allow us to dig in further.

Now I expect that would not be too helpful so we'd need to look at:

list rep.createOrUpdateFile

And

list repofiles.CreateOrUpdateRepoFile

Following the code down the slowest things to find what really is the slow cause.

The runtime.cgocall things you are seeing in the top are related to the fact that you're running sqlite. (Which you could clearly see from what points to then on the SVG you provided.)

miou-gh · 2021-02-13T01:07:16Z

All of these requests appear a little slow to me but none of them match with a slow post-receive which is what this issue was about.

Oh. I was under the impression that the two were related. I will create a new issue then. #14668

permezel · 2021-03-01T07:23:45Z

I just got my GitEA synology docker installed and have a trivial repo: nothing in it, except the branch where i deleted README.md. It is soo slow. I was sold on the claims that this was lightweight and not turgid and slow.
You might want to put some warnings on the main pages so that others don't waste time getting to the same point and then discovering that it works so poorly.

Anyway, I have beefy NAS with a 10G connexion to my client and nothing else running in Docker except an unused BitWarden. I added the nas-git as a remote to my keybase-git based repo. Keybase has to go out to the keybase servers plus locally perform various crypto ops, and I am familiar with how slow it is: not really. The nas-git takes noticeably longer to do nothing.

% pass git remote -v
nas	ssh://[email protected]/dap/passwordstore (fetch)
nas	ssh://[email protected]/dap/passwordstore (push)
origin	keybase://private/dap/passwordstore (fetch)
origin	keybase://private/dap/passwordstore (push)
% time pass git fetch origin
Initializing Keybase... done.
Syncing with Keybase... done.
pass git fetch origin  0.14s user 0.18s system 9% cpu 3.579 total
% time pass git fetch nas
pass git fetch nas  0.07s user 0.10s system 0% cpu 27.084 total

Almost 10x slower. That is impressive!

prologic · 2021-07-23T05:43:25Z

I haven't read through the entire history of this issue yet, but it seemed relevant to what I'm seeing on my instance.

I'm on 1.14.x and I'm seeing what looks like Google Bot crawling my instance with logs like:

[email protected]    | 2021/07/23 05:16:54 Started POST /prologic/go-gopher.git/git-upload-pack for 74.125.191.98:0
[email protected]    | 2021/07/23 05:16:54 Completed POST /prologic/go-gopher.git/git-upload-pack 200 OK in 324.679642ms

This is triggering high latency alarms for me that I trigger on >300ms threshold.

zeripath · 2021-07-23T06:59:49Z

~~Web crawlers like Google's robot do not POST.~~ this is incorrect google does now post when it determines it is safe to do so.

~~So some other git process is calling these.~~

In terms of performance - whilst I appreciate lots of users can't run main - 1.14 is over 400 commits behind 1.15 and there are many many improvements in 1.15.

Try the building from main or using a 1.15 RC.

If problems persist there - then report back but moaning about 1.14 performance is deeply unhelpful.

prologic · 2021-07-23T07:02:54Z

I'd love to use a later version if only you guys would push up a newer set of Docker images :) Can we do that? If not, I'll build it myself :D

prologic · 2021-07-23T07:03:17Z

Web crawlers like Google's robot do not POST.

Also as much as I believ eyou, check the logs again and the IP address. Do a whois on it :D

zeripath · 2021-07-23T07:12:13Z

I'd love to use a later version if only you guys would push up a newer set of Docker images :) Can we do that? If not, I'll build it myself :D

I pushed 1.15.0-RC2 yesterday and it's up on docker hub... But I suspect you're not using the gitea/gitea build? What build are you using?

prologic · 2021-07-23T07:22:39Z

Let me check and get back to you! Thanks! 🙇‍♂️

zeripath · 2021-07-23T07:47:23Z

Web crawlers like Google's robot do not POST.

Also as much as I believ eyou, check the logs again and the IP address. Do a whois on it :D

I stand corrected:

https://webmasters.stackexchange.com/questions/123987/googlebot-doing-post-requests

Googlebot will now do POSTs when it believes that it is safe to do so

I suspect putting your website in your recent issue means that your site is being crawled by the GoogleBot. I recommend that you create a robots.txt as per https://docs.gitea.io/en-us/search-engines-indexation/

prologic · 2021-07-23T08:07:04Z

I suspect putting your website in your recent issue means that your site is being crawled by the GoogleBot. I recommend that you create a robots.txt as per https://docs.gitea.io/en-us/search-engines-indexation/

I don't mind my instance being crawled as long as there isn't any form of abuse going on :D

prologic · 2021-07-23T08:07:21Z

But I'll read those docs anyway just in case I want to change things... 👌

zeripath added the performance/speed performance issues with slow downs label Dec 12, 2020

go-gitea deleted a comment from caifenglin Dec 8, 2021

techknowlogick closed this as completed Dec 8, 2021

go-gitea locked and limited conversation to collaborators Apr 28, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extremely slow post-receive hook of Gitea - in Docker on a Synology server #13706

Extremely slow post-receive hook of Gitea - in Docker on a Synology server #13706

obermeim commented Nov 26, 2020

techknowlogick commented Nov 26, 2020

obermeim commented Nov 26, 2020

zeripath commented Nov 27, 2020

obermeim commented Nov 27, 2020

zeripath commented Nov 27, 2020

obermeim commented Nov 27, 2020

zeripath commented Nov 27, 2020

miou-gh commented Feb 10, 2021

zeripath commented Feb 10, 2021

miou-gh commented Feb 10, 2021 •

edited

Loading

zeripath commented Feb 10, 2021

miou-gh commented Feb 11, 2021

techknowlogick commented Feb 11, 2021

miou-gh commented Feb 11, 2021

zeripath commented Feb 11, 2021

miou-gh commented Feb 11, 2021 •

edited

Loading

zeripath commented Feb 12, 2021

miou-gh commented Feb 12, 2021

zeripath commented Feb 12, 2021

miou-gh commented Feb 13, 2021

permezel commented Mar 1, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021 •

edited

Loading

prologic commented Jul 23, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021

prologic commented Jul 23, 2021

prologic commented Jul 23, 2021

Extremely slow post-receive hook of Gitea - in Docker on a Synology server #13706

Extremely slow post-receive hook of Gitea - in Docker on a Synology server #13706

Comments

obermeim commented Nov 26, 2020

Description

Logs

techknowlogick commented Nov 26, 2020

obermeim commented Nov 26, 2020

zeripath commented Nov 27, 2020

obermeim commented Nov 27, 2020

zeripath commented Nov 27, 2020

obermeim commented Nov 27, 2020

zeripath commented Nov 27, 2020

miou-gh commented Feb 10, 2021

zeripath commented Feb 10, 2021

miou-gh commented Feb 10, 2021 • edited Loading

zeripath commented Feb 10, 2021

miou-gh commented Feb 11, 2021

techknowlogick commented Feb 11, 2021

miou-gh commented Feb 11, 2021

zeripath commented Feb 11, 2021

miou-gh commented Feb 11, 2021 • edited Loading

zeripath commented Feb 12, 2021

miou-gh commented Feb 12, 2021

zeripath commented Feb 12, 2021

miou-gh commented Feb 13, 2021

permezel commented Mar 1, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021 • edited Loading

prologic commented Jul 23, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021

prologic commented Jul 23, 2021

zeripath commented Jul 23, 2021

prologic commented Jul 23, 2021

prologic commented Jul 23, 2021

miou-gh commented Feb 10, 2021 •

edited

Loading

miou-gh commented Feb 11, 2021 •

edited

Loading

zeripath commented Jul 23, 2021 •

edited

Loading