Pull Requests listing is way slower on Windows

[ramasoft-dv]

• Gitea version (or commit ref): 1.14
• Git version: 2.26.2
• Operating system: Windows Server 2016 Standard
• Database (use [x]):
  • PostgreSQL
  • MySQL
  • MSSQL
  • SQLite
• Can you reproduce the bug at https://try.gitea.io:
  • Yes (provide example URL)
  • No

In 1.13.6 it was fast when going in the Pull Requests tab.
We've migrated to 1.14 today (2024-04-11) and now it's 20x slower.
We have "ISSUE_PAGING_NUM" set to 50. And it takes 30 seconds to load the pull requests in 1.14. In 1.13.6, it took less than 1 second.
I put back the default value to 10, it's better but it still takes 5-6 seconds. I think there is a missing index or something not retro-compatible.

How can I help you to investigate the issue ?

Kind regards.

[ramasoft-dv]

It does not seems to be related to the DB. I've tried to move gitea service in another faster computer. The pull requests listing was 2x faster : 30 seconds => 15 seconds.
Moreoever, I've set SQL.Logs to true to check which query could take too much time, and actually none takes more than 1-2 ms.
So i'm pretty sure it's not comming from DB, but more from something new done after having retrieved the pull requests, while compiling informations.
Also: Accessing to individual pull request, is as fast as in 1.13.6.
So the issue come from only when accessing to Pull Requests Tab Page.

[lunny]

Could you enable pprof and paste the profile file

[ramasoft-dv]

Yes, here you are:

profile.log

[lunny]

Have you load the pull request list page when you enable pprof? It seems there is no any functions about that.

[ramasoft-dv]

Yes I did, but if it didn't worked, then I can make it again, no problem. Here you are:
profile.log

[ramasoft-dv]

This is another profile.log:

1. I started gitea service : gitea.exe
2. I logged in with my user
3. I went on the specific repository (Ramasoft.NET)
4. I clicked on Pull Requests Tab
5. I went on http://localhost:6060/debug/pprof/, clicked on "profile" which downloaded me the following file:
   profile.log

And this is what I can see in the page loading times:

[ramasoft-dv]

And this is our app.ini file (a little bit modified to remove sensible info)
app.txt

[lunny]

Could you also paste your gitea logs?

[ramasoft-dv]

Yes, of course. Here you are:

1. I changed the app.ini I provided you just earlier by defining the level of Logs to Trace
2. I started gitea service : gitea.exe
3. I logged in with my user
4. I went on the specific repository (Ramasoft.NET)
5. I clicked on Pull Requests Tab
6. I went on http://localhost:6060/debug/pprof/ and saved everything that was in this page.
7. Killed gitea service

These are the files:

1. Logs: log.txt
2. pprof files:
   block.txt
   cmdline.txt
   fullGoRoutineStackDump.txt
   goroutine.txt
   heap.txt
   mutex.txt
   profile.log
   threadcreate.txt
   trace.log
   allocs.txt

And this is how much time it took to go to Pull Request Tab:

Kind regards,
David.

[zeripath]

Thanks for extensive logging files and pprof files but please could you read https://docs.gitea.io/en-us/logging-configuration/#debugging-problems

STACKTRACE_LEVEL should generally be left unconfigured (and hence kept at none). There are only very specific occasions when it useful.

Your logs are essentially unreadable because of this setting. You have not given us the router logs so I can't tell which URL is slow.

Which url exactly is slow?

The pprof files are also in the incorrect format - pprof files should be binary files. You can get one quite easily:

wget -O  30s-cpuprofile.out 'http://localhost:6060/debug/pprof/profile?seconds=30' 

And then request the broken page whilst this is downloading.

The text files aren't really very useful at all.

The profile.log in this #15401 (comment) is in the right format but doesn't actually contain the slow page request so nothing can be inferred.

[ramasoft-dv]

Ok, no prob. I change the logging settings to the one in your documentation: Level=debug, and SQL.Log = False.

Thank you for the explanation of how pprof works. I was using it improperly.

Also for your question this is the url that is slow: http://localhost:54326/Ramasoft/Ramasoft.NET/pulls

This is what i did:

1. Change the app.ini to have the correct log level and other settings more suited for debugging
2. Run gitea service
3. Run your query (wget...)
4. Refresh the Pull Request tab

These are the files I can give to you:

30s-cpuprofile.log
logs.txt

It is ok now ?

Kind regards,
David.

[zeripath]

One quick thought.

Most Windows users have seriously long path environment variables. Windows doesn't hash this path unlike Linux and Mac.

We're mostly using git directly these days.

Set your [git] PATH correctly as this could be a cause of serious slow downs.

[zeripath]

Your logs still have stacktraces and are still missing the router logs. What is the contents of your [log] section?

Unfortunately it's now too late for me to look at your pprof output so I'll take a look tomorrow.

[ramasoft-dv]

One quick thought.

Most Windows users have seriously long path environment variables. Windows doesn't hash this path unlike Linux and Mac.

We're mostly using git directly these days.

Set your [git] PATH correctly as this could be a cause of serious slow downs.

I'll try that.
To be noted: We didn't have any slowness in 1.13.6.

[techknowlogick]

1.14 uses git itself, whereas 1.13 used a go library for some git operations, and git for the remaining operations. It is possible to build 1.14 using the go based library, it just isn't the default.

[ramasoft-dv]

Your logs still have stacktraces and are still missing the router logs. What is the contents of your [log] section?

Unfortunately it's now too late for me to look at your pprof output so I'll take a look tomorrow.

Sorry for the inconvenience. Router was set to its default value "Console" and not File, that's why I could not provide you the needed information. I fixed this and also removed stack trace.
Here are the files:
router.log
30s-cpuprofile.log
log.txt

[ramasoft-dv]

1.14 uses git itself, whereas 1.13 used a go library for some git operations, and git for the remaining operations. It is possible to build 1.14 using the go based library, it just isn't the default.

Is there a way to retrieve easily this version of gitea 1.14 using go library for git ops ? To test and see if it solves the slonesses.

[zeripath]

Have you tried setting the path to git yet? I would be seriously interested to know if that improves things.

Gogit variants are set at build-time so you would have to build gitea yourself adding the tag gogit to your tags. (Likely this would be TAGS="gogit bindata")

[zeripath]

The Log.txt you have provided is only at info level. We need debug logs.

Please could you read the link I sent you. (Actually also give us a copy of your app.ini - you never know if it's going to be enlightening.)

[ramasoft-dv]

Have you tried setting the path to git yet? I would be seriously interested to know if that improves things.

Gogit variants are set at build-time so you would have to build gitea yourself adding the tag gogit to your tags. (Likely this would be TAGS="gogit bindata")

Not yet. I'm doing that in minutes, and tell you what afterwards :)

[ramasoft-dv]

The Log.txt you have provided is only at info level. We need debug logs.

Please could you read the link I sent you. (Actually also give us a copy of your app.ini - you never know if it's going to be enlightening.)

Mmm, that's what is in your documentation. The log section is the following:

[log]
ROOT_PATH            = F:/git server/log
; Either "console", "file", "conn", "smtp" or "database", default is "console"
; Use comma to separate multiple modes, e.g. "console, file"
MODE                 = file
; Buffer length of the channel, keep it as it is if you don't know what it is.
BUFFER_LEN           = 10000
REDIRECT_MACARON_LOG = false
MACARON              = file
; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Info"
ROUTER_LOG_LEVEL     = Info
ROUTER               = file
ENABLE_ACCESS_LOG    = false
ACCESS_LOG_TEMPLATE  = {{.Ctx.RemoteAddr}} - {{.Identity}} {{.Start.Format "[02/Jan/2006:15:04:05 -0700]" }} "{{.Ctx.Req.Method}} {{.Ctx.Req.RequestURI}} {{.Ctx.Req.Proto}}" {{.ResponseWriter.Status}} {{.ResponseWriter.Size}} "{{.Ctx.Req.Referer}}\" \"{{.Ctx.Req.UserAgent}}"
ACCESS               = file
; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "Trace"
LEVEL                = Debug
; Either "Trace", "Debug", "Info", "Warn", "Error", "Critical", default is "None"
STACKTRACE_LEVEL     = None

So Level = Debug and Router_Log_Level is set to Info like in the doc.
Am I missing something ?
You can find the app.ini in the first comments. I just have changed the log section with the previous pasted infos.

[ramasoft-dv]

I've set the git path:

[git]
; The path of git executable. If empty, Gitea searches through the PATH environment.
PATH                          = "C:\Program Files\Git\bin\git.exe"

It's working, but no performance improvement.
I also set it in the PATH environment.
And tried also by restarting the computer.

[zeripath]

Argh. You're not supposed to copy app.example.ini as your app.ini!

It doesn't work like that.

You're only supposed to use it for reference to know how to set things.

That's it tomorrow morning I'm going to open a PR to remove it - it seems no one can be trusted with the damned thing.

Remove the log.XXX sections. Remove settings in the log section that aren't mentioned in the documentation.

Look through the rest of your app.ini if it's unchanged from the app.example.ini consider if you really mean it to be set.

I think the queue sections are also incorrect. Certainly the Cron sections are likely to be unhelpful.

I'm not convinced that any of these things are causing your problem but they're unhelpful.

---

Shame about the git path thing - we're sort of stuck though until I can pprof and you give me some debug logs.

[lunny]

From 30s-cpuprofile.log, it seems most time is in pull.GetLastCommitStatus, it will open git repository to get compare information which v1.13 will not. This is introduced from #13975

[ramasoft-dv]

Argh. You're not supposed to copy app.example.ini as your app.ini!

It doesn't work like that.

You're only supposed to use it for reference to know how to set things.

That's it tomorrow morning I'm going to open a PR to remove it - it seems no one can be trusted with the damned thing.

Remove the log.XXX sections. Remove settings in the log section that aren't mentioned in the documentation.

Look through the rest of your app.ini if it's unchanged from the app.example.ini consider if you really mean it to be set.

I think the queue sections are also incorrect. Certainly the Cron sections are likely to be unhelpful.

I'm not convinced that any of these things are causing your problem but they're unhelpful.

Shame about the git path thing - we're sort of stuck though until I can pprof and you give me some debug logs.

Thanks for your investigation. I'll do that :)

[ramasoft-dv]

From 30s-cpuprofile.log, it seems most time is in pull.GetLastCommitStatus, it will open git repository to get compare information which v1.13 will not. This is introduced from #13975

Is there a way to disable this functionality to see if it solves the slownesses ?
Also, this explain why the more PR are shown in the listing, the more it's slow.

[ramasoft-dv]

It's faster with the version you provided me: 14 seconds (1.14) => 9 seconds (your version). So I think your changes are a good start.
But 1.13.6 was loading pull requests in less than 1 second.
Do you need pprof files ?

[zeripath]

OK let's try the following:

https://eldritchkitty.com/~andrew/gitea-15447-git-windows-4.0-amd64.exe

https://eldritchkitty.com/~andrew/gitea-15447-gogit-windows-4.0-amd64.exe

These have the current status of #15447 built on the 1.14-branch.

[zeripath]

Do you need pprof files ?

pprof would be useful I think

[ramasoft-dv]

With 15447(git): https://eldritchkitty.com/~andrew/gitea-15447-git-windows-4.0-amd64.exe
=> from 14 seconds to 1,6 seconds (10x faster)

With 15447(go-git): https://eldritchkitty.com/~andrew/gitea-15447-gogit-windows-4.0-amd64.exe
=> from 14 seconds to 0,15 seconds (100x faster)

So the 15447 with go-git is way faster, and it's the same speed as in 1.13.6.

[zeripath]

OK - The pprofs for the 2 new ones would be helpful - I think the issue is likely going to be that GetCommit() is being called far more often that I expected and hence the extra memory use and caching of go-git is being helpful.

[ramasoft-dv]

15447(git):
15447-git-30s-cpuprofile.log

15447(go-git):
15447-gogit-30s-cpuprofile.log

[lunny]

go-git's problem is at memory not cpu.

[zeripath]

OK so this one it looks like we could reduce the calls to show-ref by collecting them together and calling show-ref for all of the refs.

[zeripath]

OK another improvement:

https://eldritchkitty.com/~andrew/gitea-15447-15455-git-windows-4.0-amd64.exe

https://eldritchkitty.com/~andrew/gitea-15447-15455-gogit-windows-4.0-amd64.exe

[ramasoft-dv]

15447-15455-git:
=> from 14 seconds to 1,5 seconds (10x faster)
=> it seems faster than 15447-git, which turned around 1,6 seconds
15447-15455-git-30s-cpuprofile.log

15447-15455-gogit:
=> from 14 seconds to 1,5 seconds (10x faster)
=> it's slower than 15447-gogit, which turned around 0,15 seconds. I was surprised, so I run again 15447-gogit, and yes the 15447-gogit is faster than the one with 15455. Maybe a problem with the version built ? (15447-15455-gogit)
15447-15455-gogit-30s-cpuprofile.log

[zeripath]

looks like the go-git one is actually still a git version... weird.

[ramasoft-dv]

Can you rebuilt the 15447-15455-gogit ? I will test it.
And also, if you want to make some other tests, do not hesitate.

Also, I found some slowness loading a specific PR, which was not that slow in 1.13.6. This PR has a lot of change requests, comments. I will create a specific issue ticket for this one, but maybe the subject is related.

[zeripath]

Can you just confirm for me that you are not running with a random AV thing that's slowing down git and that your path for the git stuff is actually reasonable? Seriously set your environment PATH so that git's binaries etc are first in order to be found.

And can you tell me how many pulls you're trying to show?

---

I've rebuilt the go-git one but I don't expect that to improve or change at all as these PRs aren't hitting that.

---

I'm a little confused by the 15447-15455-git-30s-cpuprofile.log - it's a shame that it hasn't made much difference - I made a change that should have reduced the time spent in GetRefCommitID if the refs weren't packed in a pack. I guess is that your pull refs are packed but I'm not certain. It would be useful to know if that's the case.

The reality is that the reason why the go-git one is faster is that it is just loading all the references in one shot - and keeping them in memory. Go-Git is really non-frugal with memory in general - but here it's potentially not uncalled for as realistically the number of PR heads is going to be somewhat constrained.

Now I think it may just be worth doing something similar - getting all the refs in one go as they're likely to be less than 4kb in general.

[ramasoft-dv]

Can you just confirm for me that you are not running with a random AV thing that's slowing down git and that your path for the git stuff is actually reasonable? Seriously set your environment PATH so that git's binaries etc are first in order to be found.

Nope, on that computer there is only windows defender.
The path for git is short, you can see it in that comment: #15401 (comment)

And can you tell me how many pulls you're trying to show?

50

I've rebuilt the go-git one but I don't expect that to improve or change at all as these PRs aren't hitting that.

With your rebuilt, it's now turning around 0,1s. So the 15447-15455-gogit is the fastest version you have provided me, right now.
Comparatively, the 15447-gogit was running the pull requests list in around 0,15s.

I'm a little confused by the 15447-15455-git-30s-cpuprofile.log - it's a shame that it hasn't made much difference - I made a change that should have reduced the time spent in GetRefCommitID if the refs weren't packed in a pack. I guess is that your pull refs are packed but I'm not certain. It would be useful to know if that's the case.
The reality is that the reason why the go-git one is faster is that it is just loading all the references in one shot - and keeping them in memory. Go-Git is really non-frugal with memory in general - but here it's potentially not uncalled for as realistically the number of PR heads is going to be somewhat constrained.
Now I think it may just be worth doing something similar - getting all the refs in one go as they're likely to be less than 4kb in general.

How can I help you to investigate this ?

[zeripath]

By path I mean your environment path.

Git on Windows calls a lot of sub programs so it also needs to look these up on the path.

---

To check the refs pack status you would have to go in to the git repository directly and check which refs/pulls/XXX/head were files versus how many are returned from git for-each-ref refs/pulls (it might be pull rather than pulls though I can never remember)

[ramasoft-dv]

By path I mean your environment path.

Git on Windows calls a lot of sub programs so it also needs to look these up on the path.

Yes it's already done. Please check the comment link.
So it's done in app.ini and environment path.

To check the refs pack status you would have to go in to the git repository directly and check which refs/pulls/XXX/head were files versus how many are returned from git for-each-ref refs/pulls (it might be pull rather than pulls though I can never remember)

I'll try that later and tell you what.

[zeripath]

still not completely solved I think

[ramasoft-dv]

In my opinion with: 15447-15455-gogit, we have a solution for my problem. Is this solution will be available in the next 1.14.1 ?
But, we need to have both builds available for one who needs gogit in order to have something fast. Or maybe a way to switch between gogit and git ?

For "To check the refs pack status you would have to go in to the git repository directly and check which refs/pulls/XXX/head were files versus how many are returned from git for-each-ref refs/pulls (it might be pull rather than pulls though I can never remember)". I didn't have yet the time to check, sorry. I will have time on the weekend.

[zeripath]

@ramasoft-dv was this fixed on 1.15?

[ramasoft-dv]

Nope. I have 1.15.7 and it still fails.

-------------------------

On 2021-12-15 13:29, zeripath wrote: @ramasoft-dv [1] was this fixed on 1.15? -- You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub [2], or unsubscribe [3]. Triage notifications on the go with GitHub Mobile for iOS [4] or Android [5].

Links: ------ [1] https://github.com/ramasoft-dv [2] #15401 (comment) [3] https://github.com/notifications/unsubscribe-auth/ARREQNLKGATBRCAWGJP6RJLURCCZJANCNFSM42XVLTMQ [4] https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 [5] https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub

[zeripath]

Any chance you could try #17992 to see if that finally solves the issue?

[zeripath]

Sorry that is #17992

[wxiaoguang]

No more feedback, I think this issue can be closed, feel free to reopen if there are more clues.