High Idle CPU usage (fresh install)

[elmodor]

• Gitea version (or commit ref): 1.14.1 (rootless)
• Git version: 2.30.2
• Operating system: Debian 10, amd64, Intel Celeron N4100 (quad-core 1.1 GHz, up to 2.4 GHz)
• Docker: Docker 19.03.13, Compose: 1.27.4
• 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

I have a high idle CPU usage with my upgraded gitea server, so I tried a fresh deployment and have the same issue.
After a fresh install (even 1 hour after) the CPU% usage is about 5% of my system. One user, no repository.
In my testing VM (also Debian 10, 1 CPU thread only) the idle CPU% usage is about 0,1% (with the exact same docker-compose.yml and configuration).
This happens with 14.1 root or rootless version. (haven't tried others)

I know 5% is not that high, but should it really be that much with a fresh install and while idle?

According to htop the CPU is used by /usr/local/bin/gitea -c /etc/gitea/app.ini web. I've set the logging to debug but there's no logs when being idle.

Any help is appreciated :)

Screenshots

[tinxx]

I'm seeing the same behaviour on my machine.

I have activated the access log to make sure no one is accessing my Gitea instance and triggering something.
It is definitely idle load.

On Log Level "Info" I can see a log like this every 10 seconds (:05, :15, :25, ...):

2021/04/26 17:45:55 ...dels/notification.go:734:GetUIDsAndNotificationCounts() [I] [SQL] SELECT user_id, count(*) AS count FROM notification WHERE user_id IN (SELECT user_id FROM notification WHERE updated_unix >= ? AND updated_unix < ?) AND status = ? GROUP BY user_id [1619459143 1619459153 1] - 577.264µs

Can you confirm that?

Cheers,
Tinxx

[systemdarena]

I am also noticing a CPU usage that seems high for gitea being idle with no usage at all. On my server that also hosts samba shares that are used every day, and other standard services like chrony, rsyslogd, crond, and firewalld(a python daemon!), gitea had the highest TIME value on my server after 24 days, by a large amount. I also see the SQL query lines every 10 seconds, but I don't think that is the issue, since that only runs every 10 seconds, and I see the cpu usage spikes seem to be pretty constant, though it jumps between threads. The parent process will be at 1% or 2% CPU usage according to htop with the refresh set to 1 second. With htop's refresh set to much shorter, like 0.1 seconds then it jumps from 0% to 8% back and forth constantly.

What may be more telling is the strace output, which shows a constant polling of epoll_pwait() on several threads:

[pid 944513] 14:39:28.794308 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.794348 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.794389 <... epoll_pwait resumed>[], 128, 0, NULL, 824674766514) = 0
[pid 944547] 14:39:28.794424 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.794460 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.794498 futex(0xc00280e150, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944514] 14:39:28.797018 <... nanosleep resumed>NULL) = 0
[pid 944514] 14:39:28.797112 futex(0x595ee58, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=16761648} <unfinished ...>
[pid 944513] 14:39:28.813747 <... epoll_pwait resumed>[], 128, 19, NULL, 19) = 0
[pid 944513] 14:39:28.813841 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.813953 epoll_pwait(3, <unfinished ...>
[pid 944514] 14:39:28.814087 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 944514] 14:39:28.814158 nanosleep({tv_sec=0, tv_nsec=10000000}, <unfinished ...>
[pid 944513] 14:39:28.815166 <... epoll_pwait resumed>[], 128, 1, NULL, 19) = 0
[pid 944513] 14:39:28.815263 futex(0xc00280e150, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944547] 14:39:28.815395 <... futex resumed>) = 0
[pid 944513] 14:39:28.815425 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.815470 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.815510 <... epoll_pwait resumed>[], 128, 0, NULL, 824765049992) = 0
[pid 944547] 14:39:28.815546 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.815583 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.815622 futex(0xc00280e150, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944514] 14:39:28.824461 <... nanosleep resumed>NULL) = 0
[pid 944514] 14:39:28.824553 futex(0x595ee58, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=2534876} <unfinished ...>
[pid 944513] 14:39:28.826860 <... epoll_pwait resumed>[], 128, 11, NULL, 19) = 0
[pid 944513] 14:39:28.826973 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.827089 epoll_pwait(3, <unfinished ...>
[pid 944514] 14:39:28.827298 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 944514] 14:39:28.827369 nanosleep({tv_sec=0, tv_nsec=10000000}, <unfinished ...>
[pid 944513] 14:39:28.828289 <... epoll_pwait resumed>[], 128, 1, NULL, 19) = 0
[pid 944513] 14:39:28.828379 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.828495 futex(0xc00280e150, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944547] 14:39:28.828617 <... futex resumed>) = 0
[pid 944513] 14:39:28.828646 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.828686 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.828727 <... epoll_pwait resumed>[], 128, 0, NULL, 824707085640) = 0
[pid 944547] 14:39:28.828761 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.828797 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.828836 futex(0xc00280e150, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944514] 14:39:28.837662 <... nanosleep resumed>NULL) = 0
[pid 944514] 14:39:28.837754 futex(0x595ee58, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=28499131} <unfinished ...>
[pid 944513] 14:39:28.866087 <... epoll_pwait resumed>[], 128, 37, NULL, 19) = 0
[pid 944513] 14:39:28.866181 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.866293 epoll_pwait(3, <unfinished ...>
[pid 944514] 14:39:28.866464 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 944514] 14:39:28.866536 nanosleep({tv_sec=0, tv_nsec=10000000}, <unfinished ...>
[pid 944513] 14:39:28.867492 <... epoll_pwait resumed>[], 128, 1, NULL, 19) = 0
[pid 944513] 14:39:28.867585 futex(0xc00280e150, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944547] 14:39:28.867717 <... futex resumed>) = 0
[pid 944513] 14:39:28.867747 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.867794 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.867827 <... epoll_pwait resumed>[], 128, 0, NULL, 824697945778) = 0
[pid 944547] 14:39:28.867862 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.867917 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.867952 futex(0xc00280e150, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944514] 14:39:28.876822 <... nanosleep resumed>NULL) = 0
[pid 944514] 14:39:28.876919 futex(0x595ee58, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=10181233} <unfinished ...>
[pid 944513] 14:39:28.887213 <... epoll_pwait resumed>[], 128, 19, NULL, 19) = 0
[pid 944513] 14:39:28.887311 epoll_pwait(3, <unfinished ...>
[pid 944514] 14:39:28.887354 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 944513] 14:39:28.887400 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944514] 14:39:28.887437 nanosleep({tv_sec=0, tv_nsec=10000000}, <unfinished ...>
[pid 944513] 14:39:28.887495 futex(0xc00280e150, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 944547] 14:39:28.887566 <... futex resumed>) = 0
[pid 944513] 14:39:28.887595 <... futex resumed>) = 1
[pid 944547] 14:39:28.887628 futex(0xc000680950, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944530] 14:39:28.887740 <... futex resumed>) = 0
[pid 944547] 14:39:28.887768 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.887802 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.887848 <... epoll_pwait resumed>[], 128, 0, NULL, 824672440224) = 0
[pid 944530] 14:39:28.887877 epoll_pwait(3, <unfinished ...>
[pid 944513] 14:39:28.887924 <... epoll_pwait resumed>[], 128, 0, NULL, 824701657488) = 0
[pid 944547] 14:39:28.887963 epoll_pwait(3, <unfinished ...>
[pid 944530] 14:39:28.887993 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944513] 14:39:28.888028 futex(0x595f6d0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944530] 14:39:28.888070 futex(0xc000680950, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944547] 14:39:28.894220 <... epoll_pwait resumed>[], 128, 6, NULL, 19) = 0
[pid 944547] 14:39:28.894315 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944547] 14:39:28.894437 futex(0xc000680950, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944530] 14:39:28.894563 <... futex resumed>) = 0
[pid 944547] 14:39:28.894599 epoll_pwait(3, <unfinished ...>
[pid 944530] 14:39:28.894644 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.894677 <... epoll_pwait resumed>[], 128, 0, NULL, 824677068466) = 0
[pid 944530] 14:39:28.894714 <... epoll_pwait resumed>[], 128, 0, NULL, 0) = 0
[pid 944547] 14:39:28.894749 epoll_pwait(3, <unfinished ...>
[pid 944530] 14:39:28.894789 futex(0xc000680950, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 944514] 14:39:28.897652 <... nanosleep resumed>NULL) = 0
[pid 944514] 14:39:28.897739 futex(0x595ee58, FUTEX_WAIT_PRIVATE, 0, {tv_sec=0, tv_nsec=17650309} <unfinished ...>
[pid 944547] 14:39:28.915023 <... epoll_pwait resumed>[], 128, 20, NULL, 19) = 0
[pid 944547] 14:39:28.915115 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944547] 14:39:28.915219 epoll_pwait(3, <unfinished ...>
[pid 944514] 14:39:28.915536 <... futex resumed>) = -1 ETIMEDOUT (Connection timed out)
[pid 944514] 14:39:28.915603 nanosleep({tv_sec=0, tv_nsec=10000000}, <unfinished ...>
[pid 944547] 14:39:28.916414 <... epoll_pwait resumed>[], 128, 1, NULL, 19) = 0
[pid 944547] 14:39:28.916505 epoll_pwait(3, [], 128, 0, NULL, 0) = 0
[pid 944547] 14:39:28.916609 futex(0xc000680950, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 944547] 14:39:28.916735 epoll_pwait(3, <unfinished ...>
[pid 944530] 14:39:28.916770 <... futex resumed>) = 0
[pid 944547] 14:39:28.916805 <... epoll_pwait resumed>[], 128, 0, NULL, 824707085960) = 0
[pid 944530] 14:39:28.916841 epoll_pwait(3, <unfinished ...>
[pid 944547] 14:39:28.916880 epoll_pwait(3, <unfinished ...>

[techknowlogick]

There are various scheduled tasks that happen periodically, what would be most helpful is information from pprof (specifically the diagram it provides) as then CPU usage could be traced throughout the codebase.

[ddan39]

big surprise...

pprof001.svg.pdf

i guess strace doesn't lie. i just wasted over an hour of my time for that stupid pprof that strace already clearly showed us.

[zeripath]

@ddan39 if you had given us the out file instead of the svg we could have looked at what was causing the poll waits.

You may find changing your queue configurations may change the number of polling.

In terms of the GetUIDsAndNotificationCounts this is simply the eventsource - if you do not want it to run turn it off. (see https://docs.gitea.io/en-us/config-cheat-sheet/#ui---notification-uinotification)

[ddan39]

Ah, yeah, It was getting late and I was getting a bit frustrated trying to get pprof to even work when I have zero go knowledge. Sorry about responding a bit harshly. I was going to upload more files(well to be honest, I was trying to upload svg first, which was denied) but github was only letting me attach certain file types to the comments. I probably should've just zipped them both together... it looks like .zip files are allowed. When I get off work I will attach some more files.

I will look into the queue settings, thanks.

I was surprised to see gitea seemingly polling the epoll_wait function so fast like that to be honest. With go being all about concurrency I figured it could just do a long blocking call... but again, I'm a newb here.

[elmodor]

I got pprof and strace running inside the docker of gitea:

docker exec -u root -it gitea22 /bin/bash
apk add strace go graphviz
export GOPATH=/
go get -u github.com/google/pprof
strace/pprof /usr/local/bin/gitea -c /etc/gitea/app.ini web

But whenever I try to kill the running gitea process to try to start it with pprof or strace I get booted out of the container. How do I run this inside the docker container?

[ddan39]

edit: removed bad info about pprof, easy to use it below

to get profile, simply add to your app.ini [server] section ENABLE_PPROF = true and then after gitea has been running for a while run the command go tool pprof -top ./path/to/gitea-bin http://127.0.0.1:6060/

[jolheiser]

Gitea has pprof http endpoints built in.

See https://docs.gitea.io/en-us/config-cheat-sheet/#server-server

[ddan39]

well, shit.

[elmodor]

So thanks to Etzelia in Discord I got pprof to run.
Heres a short guide on how to do it:
#14772

Here is my output of 10min, this is a fresh rootless docker install. No repo, one user. Docker stats showed around 4-5% CPU usage of my host system (with a 1sec refresh rate of docker stats):

(pprof) top  
Showing nodes accounting for 12960ms, 76.10% of 17030ms total  
Dropped 130 nodes (cum <= 85.15ms)  
Showing top 10 nodes out of 64
      flat  flat%   sum%        cum   cum%
    7080ms 41.57% 41.57%     7080ms 41.57%  runtime.epollwait
    2820ms 16.56% 58.13%     2820ms 16.56%  runtime.futex
     920ms  5.40% 63.53%    12680ms 74.46%  runtime.findrunnable
     610ms  3.58% 67.12%      830ms  4.87%  runtime.nanotime (inline)
     480ms  2.82% 69.94%     7560ms 44.39%  runtime.netpoll
     220ms  1.29% 71.23%     1030ms  6.05%  runtime.checkTimers
     220ms  1.29% 72.52%      220ms  1.29%  runtime.nanotime1
     220ms  1.29% 73.81%      310ms  1.82%  runtime.scanobject
     200ms  1.17% 74.99%      230ms  1.35%  runtime.pidleget
     190ms  1.12% 76.10%      190ms  1.12%  runtime.(*mcache).prepareForSweep

and second run

(pprof) top
Showing nodes accounting for 5270ms, 69.07% of 7630ms total
Dropped 86 nodes (cum <= 38.15ms)
Showing top 10 nodes out of 87
      flat  flat%   sum%        cum   cum%
    1940ms 25.43% 25.43%     1940ms 25.43%  runtime.epollwait
    1880ms 24.64% 50.07%     1880ms 24.64%  runtime.futex
     330ms  4.33% 54.39%     4400ms 57.67%  runtime.findrunnable
     290ms  3.80% 58.19%      500ms  6.55%  runtime.selectgo
     210ms  2.75% 60.94%      310ms  4.06%  runtime.scanobject
     150ms  1.97% 62.91%      220ms  2.88%  runtime.nanotime (inline)
     130ms  1.70% 64.61%      130ms  1.70%  runtime.heapBitsSetType
     120ms  1.57% 66.19%     2060ms 27.00%  runtime.netpoll
     120ms  1.57% 67.76%      140ms  1.83%  runtime.sellock
     100ms  1.31% 69.07%      150ms  1.97%  runtime.lock2

I attached the pprof output. Loadable with: go tool pprof pprof.out

pprof1.pdf
pprof2.pdf
pprofs.zip

[elmodor]

@jolheiser Can you do anything with those pprofs?

[zeripath]

I mean these are pretty low-level go runtime issues to do with selects and polling. I've put up a PR that might(?) help if it's the case that it's due to having too many go-routines waiting on selects that are to blame.

Could you try building #15686 to see if this helps?