Hello,
I run a private server for a handful of repositories with about a dozen users. The hardware is a RaspberryPi 4, which has met our needs well so far. But now we’re experiencing a weird delay/hang when trying to view code of one specific repository. When the browser requests the “Code” tab (for example) Gitea seems to stop responding (I suspect before it has even sent any response, but I’m not certain of this), and the browser eventually times-out. We see the same behaviour when trying to view commits directly (e.g., changed files in a pull-request).
All other pages seem to be unaffected, including code pages of other repos. The affected repo is not even the largest repo we have, although it is the most active and has the most commits (~2000).
I tried logging at trace level, and the following is what I saw (some names removed for privacy). When the browser requests the code page:
2024-02-26T12:59:41.618585-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/process/manager.go:188:Add() [T] Start 65dcd18d: GET: /ORGNAME/REPONAME (request)
2024-02-26T12:59:41.619342-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...eb/routing/logger.go:47:func1() [T] router: started GET /ORGNAME/REPONAME for 192.168.0.1:0
2024-02-26T12:59:41.620168-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...ices/auth/session.go:50:SessionUser() [T] Session Authorization: Found user[1]
2024-02-26T12:59:41.621505-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...ices/auth/session.go:66:SessionUser() [T] Session Authorization: Logged in user <User 1:USERNAME>
2024-02-26T12:59:41.629306-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 models/repo/repo.go:352:LoadUnits() [T] repo.Units, ID=4, Types: [TypeCode, TypeIssues, TypePullRequests, TypeReleases, TypeWiki, TypeProjects, TypePackages]
2024-02-26T12:59:41.629691-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/repo_permission.go:140:func1() [T] Permission Loaded for <User 1:USERNAME> in <Repository 4:ORGNAME/REPONAME>:
2024-02-26T12:59:41.630170-05:00 HOSTNAME gitea[1921]: Permissions: {AccessMode:owner Units:[0x4000c1ff80 0x40059ea600 0x40059eb170 0x40059ebf80 0x40068368a0 0x4006837110 0x4006837740] UnitsMode:map[]}
2024-02-26T12:59:41.636964-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...dules/git/command.go:290:Run() [D] git.Command.RunDir(/home/git/repositories/ORGNAME/REPONAME.git): /usr/bin/git -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= rev-parse
2024-02-26T12:59:41.637360-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/process/manager.go:188:Add() [T] Start 65dcd18d-2: /usr/bin/git rev-parse [repo_path: /home/git/repositories/ORGNAME/REPONAME.git] (from 65dcd18d) (normal)
2024-02-26T12:59:41.642842-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/process/manager.go:231:remove() [T] Done 65dcd18d-2: /usr/bin/git rev-parse [repo_path: /home/git/repositories/ORGNAME/REPONAME.git]
2024-02-26T12:59:41.644007-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...dules/git/command.go:290:Run() [D] git.Command.RunDir(/home/git/repositories/ORGNAME/REPONAME.git): /usr/bin/git -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= cat-file --batch
2024-02-26T12:59:41.645137-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/process/manager.go:188:Add() [T] Start 65dcd18d-3: /usr/bin/git cat-file --batch [repo_path: /home/git/repositories/ORGNAME/REPONAME.git] (modules/context/repo.go:631) (from 65dcd18d) (normal)
2024-02-26T12:59:41.645278-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...dules/git/command.go:290:Run() [D] git.Command.RunDir(/home/git/repositories/ORGNAME/REPONAME.git): /usr/bin/git -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= cat-file --batch-check
2024-02-26T12:59:41.645567-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:41 ...s/process/manager.go:188:Add() [T] Start 65dcd18d-4: /usr/bin/git cat-file --batch-check [repo_path: /home/git/repositories/ORGNAME/REPONAME.git] (modules/context/repo.go:631) (from 65dcd18d) (normal)
2024-02-26T12:59:44.843548-05:00 HOSTNAME gitea[1921]: 2024/02/26 12:59:44 ...eb/routing/logger.go:68:func1() [W] router: slow GET /ORGNAME/REPONAME for 192.168.0.1:0, elapsed 3224.8ms @ repo/middlewares.go:17(repo.SetEditorconfigIfExists)
(Omitting some Cron tasks and other noise.) Eventually the browser times-out (I think), triggering this:
2024-02-26T13:11:49.615286-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...ers/web/repo/view.go:675:checkHomeCodeViewable() [E] ReadBy: context canceled
2024-02-26T13:11:49.615720-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 .../context_response.go:68:HTML() [D] Template: status/500
2024-02-26T13:11:49.615858-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...dules/git/command.go:344:Run() [D] slow git.Command.Run: /usr/bin/git -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= cat-file --batch-check (12m7.970868975s)
2024-02-26T13:11:49.615973-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...s/process/manager.go:231:remove() [T] Done 65dcd18d-4: /usr/bin/git cat-file --batch-check [repo_path: /home/git/repositories/ORGNAME/REPONAME.git] (modules/context/repo.go:631)
2024-02-26T13:11:49.616062-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...dules/git/command.go:344:Run() [D] slow git.Command.Run: /usr/bin/git -c protocol.version=2 -c credential.helper= -c filter.lfs.required= -c filter.lfs.smudge= -c filter.lfs.clean= cat-file --batch (12m7.971228047s)
2024-02-26T13:11:49.616156-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...s/process/manager.go:231:remove() [T] Done 65dcd18d-3: /usr/bin/git cat-file --batch [repo_path: /home/git/repositories/ORGNAME/REPONAME.git] (modules/context/repo.go:631)
2024-02-26T13:11:49.616352-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ORGNAME/REPONAME for 192.168.0.1:0, 500 Internal Server Error in 727998.1ms @ repo/view.go:730(repo.Home)
2024-02-26T13:11:49.616481-05:00 HOSTNAME gitea[1921]: 2024/02/26 13:11:49 ...s/process/manager.go:231:remove() [T] Done 65dcd18d: GET: /ORGNAME/REPONAME
The REPONAME.git git repo itself seems fine: pull from clients works, and manual fsck/gc directly on the server completes successfully and quickly. I can even run those git commands marked as “slow” in the log (adding --batch-all-objects arg to make them do something) and they complete in a fraction of a second as you’d expect.
I’m confident that it was working fine a week ago; possibly even more recently than that. There haven’t been any massive commits since then. Coincidentally, a day or two ago I upgraded from 1.21.3 to 1.21.6. I can’t say whether or not this particular behaviour became present at that point, but it’s possible.
Anyone have any ideas, a cause, a workaround, or how to dig into this further?