search

go-gitea / gitea

Git with a cup of tea! Painless self-hosted all-in-one software development service, including Git hosting, code review, team collaboration, package registry and CI/CD
https://gitea.com
MIT License
44.1k stars 5.41k forks source link

Index page incredibly slow after update to 1.21.8 #29769

Open SoulSeekkor opened 6 months ago

SoulSeekkor commented 6 months ago

Description

Updated from 1.21.7 to 1.21.8 and now the index page takes almost 10 seconds to load, it's insanely slow now... seems to be the heat map that is holding everything up?

Gitea Version

1.21.8

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

No response

Screenshots

image

Git Version

2.42.0, Wire Protocol Version 2 Enabled

Operating System

Windows Server 2019

How are you running Gitea?

As a Windows service using the provided binary.

Database

MSSQL

lunny commented 6 months ago

Can you force-reload this page and try again?

SoulSeekkor commented 6 months ago

Force reload (in Chrome) and it didn't have any effect. Also loaded in Firefox (which I don't use for anything except testing so it's never hit the site before) and it had the same performance problem.

SoulSeekkor commented 6 months ago

Quick update, my coworker appears to not have this issue even after hard refreshes. I STILL have the issue however, even after hitting it locally on the server itself with Edge. I have a feeling this is specific to administrative users.

lunny commented 6 months ago

Can you provide some backend logs and web browser console -> network screenshots?

SoulSeekkor commented 6 months ago

Sure, here is the contents of the log after clearing it and refreshing the main page a few times:

2024/03/13 11:51:10 ...es/setting/mailer.go:203:loadMailerFrom() [W] connecting over insecure SMTP protocol to non-local address is not recommended 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table system_setting Column version db default is , struct default is 1 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table attachment column uuid db type is NVARCHAR(40), struct type is VARCHAR(40) 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table upload column uuid db type is NVARCHAR(40), struct type is VARCHAR(40) 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table project column card_type db type is INT, struct type is BIGINT 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table project Column card_type db default is 0, struct default is 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table project Column card_type db nullable is false, struct nullable is true 2024/03/13 11:51:10 cmd/web.go:194:serveInstalled() [W] Table hook_task has column repo_id but struct has not related field 2024/03/13 11:51:38 ...eb/routing/logger.go:68:func1() [W] router: slow GET / for 10.5.4.131:63770, elapsed 3866.0ms @ web/home.go:32(web.Home) 2024/03/13 11:52:02 ...eb/routing/logger.go:68:func1() [W] router: slow GET / for 10.5.4.131:63770, elapsed 3799.7ms @ web/home.go:32(web.Home) 2024/03/13 11:52:23 ...eb/routing/logger.go:68:func1() [W] router: slow GET / for 10.5.4.131:63770, elapsed 3310.2ms @ web/home.go:32(web.Home)

SoulSeekkor commented 6 months ago

Here are the screenshots. waterfall3 waterfall1 waterfall2

rwalravens commented 6 months ago

We're experiencing the same, although for some users it already started in 1.21.1 We suspect it has something to do with the action table. After launching the cron 'Delete all old actions from database', the performance is much better (for our company, the table shrunk from ~2 million to 500k rows). Of course this bypasses the cause, but it can help while waiting for a fix.

SoulSeekkor commented 6 months ago

I know in one particular older version (not sure if it was 1.21.1 off hand), the main page performance dropped drastically but I believe it was the org/repos listing that took forever at that time.

lunny commented 5 months ago

29905 & #29932 maybe helpful.

SoulSeekkor commented 5 months ago

Looks promising!

SoulSeekkor commented 5 months ago

Just noting that after updating to 1.21.9 this morning, it didn't make any difference on this page load issue for me.

yp05327 commented 5 months ago

If heatmap is related, maybe this issue is related: #21045

SoulSeekkor commented 5 months ago

Possibly but I doubt it, the heatmap (despite a fair number of repos on our instance) wasn't an issue before until 1.21.8, something changed in that (and seems to be only affecting admins) that absolutely made the main page almost unusable at this point. Also noting (probably expected) that the latest 1.21.10 version performance is unchanged.

yp05327 commented 5 months ago

maybe we need a trace level log to detect where takes long time to handle the request.

SoulSeekkor commented 5 months ago

I stopped the service, cleared the log, set to trace level, and after starting the service refreshed the main page and stopped it again. Hopefully this helps!

lunny commented 5 months ago

Thank you. It's very helpful.

SoulSeekkor commented 3 months ago

Just a quick update on this, I've updated our instance to 1.22.0 and this is still an issue. Before the update I also converted the entirety of the database collation to the recommended Latin1_General_CS_AS as well (to no effect).

lunny commented 3 months ago

Can you post the backend logs when you visit the dashboard after enable database logs? https://docs.gitea.com/next/administration/logging-config?_highlight=log_sql#the-xorm-logger

And if yo can visit the database, please do a count on action table, so that we know how many records there.

SoulSeekkor commented 3 months ago

I've attached the requested log, cleared it first followed by service start, refreshed dashboard, stopped service. The count of the action table is 139,460.

gitea.log

SoulSeekkor commented 3 months ago

Interesting bit to add to this, I noticed yesterday when I had filled the entire feed with commits that were only mine that the index page loaded in a second or two (normal). Today now that the feed has other commits (synced commits for mirrors in orgs) it's back to being super super slow again to refresh.

hawkbee commented 2 months ago

The slow dashboard happened on gitea 1.21.9, some logs may be usefull.

mysql  Ver 14.14 Distrib 5.7.42
gitea 当前版本: 1.21.9 页面:1868ms 模板:150ms
2024/07/05 11:27:37 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /org/test/dashboard for 192.168.100.120:50062, elapsed 3439.9ms @ user/home.go:73(user.Dashboard)
2024/07/05 11:27:47 ...eb/routing/logger.go:102:func1() [I] router: completed GET /avatars/527798c2fac472a9aa2877e4ea29f5b0?size=56 for 192.168.100.120:50074, 200 OK in 47.5ms @ web/base.go:22(avatars)
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:47 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:48 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:48 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:48 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:48 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13950453902916295058 6316367925459460 0x6735640} false}
2024/07/05 11:27:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /org/test/dashboard for 192.168.100.120:50062, 200 OK in 15709.9ms @ user/home.go:73(user.Dashboard)
2
SoulSeekkor commented 2 months ago

Just adding that this is still an issue with 1.22.1.

somera commented 1 month ago

I see this

2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:57 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}
2024/08/01 22:36:58 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13953025034712252310 18263062709511 0x6a1a080} false}

to in my gitea 1.22.1 on ubuntu with PostgreSQL.

somera commented 1 month ago

The "cache context is expired, may be misused..." log entry I see in #31752.

lixfel commented 1 month ago

I have the same issue with the slow home page / user page on my gitea instance. Due to the suspected heatmap, I tested the performance with ENABLE_USER_HEATMAP = false. This resulted in no noticable change in performance. Due to this I suspect not the heatmap but the user/home/activity feed as the culprit.

somera commented 1 month ago

@lixfel do you see slow queries in gitea.log?

lixfel commented 1 month ago

Yes (MariaDB backend). Time of the query roughly matches reported page load time for (logged in) / and /user?tab=activity page:

2024/08/12 16:11:31 ...activities/action.go:461:GetFeeds() [W] [Slow SQL Query] SELECT `action`.* FROM `action` INNER JOIN `repository` ON `repository`.id = `action`.repo_id WHERE user_id=? AND act_user_id=? AND is_deleted=? ORDER BY `action`.`created_unix` DESC LIMIT 5 [13 13 false] - 33.760273009s

I have also found these queries (just once, not for every slow page load):

2024/08/12 11:45:58 ...activities/action.go:461:GetFeeds() [W] [Slow SQL Query] SELECT `action`.* FROM `action` INNER JOIN `repository` ON `repository`.id = `action`.repo_id WHERE act_user_id IN (SELECT `user`.id FROM `user` WHERE keep_activity_private=? AND visibility=?) AND repo_id IN (SELECT id FROM repository WHERE (`repository`.is_private=? AND `repository`.owner_id NOT IN (SELECT id FROM `user` WHERE type=? AND visibility IN (?,?)))) AND user_id=? AND act_user_id=? AND `action`.is_private=? AND is_deleted=? ORDER BY `action`.`created_unix` DESC LIMIT 5 [false public false 1 private limited 13 13 false false] - 34.155154395s
2024/08/12 11:46:30 ...activities/action.go:461:GetFeeds() [W] [Slow SQL Query] SELECT count(*) FROM `action` INNER JOIN `repository` ON `repository`.id = `action`.repo_id WHERE act_user_id IN (SELECT `user`.id FROM `user` WHERE keep_activity_private=? AND visibility=?) AND repo_id IN (SELECT id FROM repository WHERE (`repository`.is_private=? AND `repository`.owner_id NOT IN (SELECT id FROM `user` WHERE type=? AND visibility IN (?,?)))) AND user_id=? AND act_user_id=? AND `action`.is_private=? AND is_deleted=? [false public false 1 private limited 13 13 false false] - 31.342845667s
somera commented 1 month ago

I'm using Gitea with PostgreSQL. I can't check the statements on my setup.

Just try to analyse the statements with ANALYSE (https://mariadb.com/kb/en/analyze-statement/). And post the output here.

lixfel commented 1 month ago

Context: ~122k Actions (I have in the meantime set the recommended old action cleanup up, therefore slightly shorter times).

1. Statement ```json { "query_optimization": { "r_total_time_ms": 0.224562772 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 14692.04853, "filesort": { "sort_key": "`action`.created_unix desc", "r_loops": 1, "r_total_time_ms": 0.310724109, "r_limit": 5, "r_used_priority_queue": true, "r_output_rows": 6, "r_sort_mode": "sort_key,rowid", "temporary_table": { "nested_loop": [ { "table": { "table_name": "repository", "access_type": "index", "possible_keys": ["PRIMARY"], "key": "IDX_repository_is_fork", "key_length": "1", "used_key_parts": ["is_fork"], "r_loops": 1, "rows": 101, "r_rows": 101, "r_table_time_ms": 0.128251931, "r_other_time_ms": 0.164203069, "r_engine_stats": { "pages_accessed": 1 }, "filtered": 100, "r_filtered": 100, "using_index": true } }, { "table": { "table_name": "action", "access_type": "ref", "possible_keys": [ "IDX_action_user_id", "IDX_action_au_r_c_u_d", "IDX_action_r_u_d" ], "key": "IDX_action_r_u_d", "key_length": "19", "used_key_parts": ["repo_id", "user_id", "is_deleted"], "ref": ["gitea.repository.id", "const", "const"], "r_loops": 101, "rows": 129, "r_rows": 258.2079208, "r_table_time_ms": 14677.53835, "r_other_time_ms": 12.82903396, "r_engine_stats": { "pages_accessed": 78573, "pages_read_count": 8730, "pages_read_time_ms": 49065154.15 }, "filtered": 27.69502831, "r_filtered": 4.022393497, "attached_condition": "`action`.act_user_id = 1" } } ] } } } } ```
2. Statement ```json { "query_optimization": { "r_total_time_ms": 0.46650906 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 15869.32961, "filesort": { "sort_key": "`action`.created_unix desc", "r_loops": 1, "r_total_time_ms": 0.49666901, "r_limit": 5, "r_used_priority_queue": true, "r_output_rows": 6, "r_sort_mode": "sort_key,rowid", "temporary_table": { "nested_loop": [ { "table": { "table_name": "user", "access_type": "const", "possible_keys": ["PRIMARY"], "key": "PRIMARY", "key_length": "8", "used_key_parts": ["id"], "ref": ["const"], "r_loops": 0, "rows": 1, "r_rows": null, "r_engine_stats": { "pages_accessed": 1 }, "filtered": 100, "r_filtered": null } }, { "table": { "table_name": "repository", "access_type": "range", "possible_keys": ["PRIMARY", "IDX_repository_is_private"], "key": "IDX_repository_is_private", "key_length": "2", "used_key_parts": ["is_private"], "r_loops": 1, "rows": 67, "r_rows": 67, "r_table_time_ms": 0.365640891, "r_other_time_ms": 0.387999654, "r_engine_stats": { "pages_accessed": 135 }, "filtered": 100, "r_filtered": 76.11940299, "index_condition": "repository.is_private = 0", "attached_condition": "!(repository.owner_id,repository.owner_id in (subquery#4))" } }, { "table": { "table_name": "repository", "access_type": "eq_ref", "possible_keys": ["PRIMARY"], "key": "PRIMARY", "key_length": "8", "used_key_parts": ["id"], "ref": ["gitea.repository.id"], "r_loops": 51, "rows": 1, "r_rows": 1, "r_table_time_ms": 0.300514901, "r_other_time_ms": 0.032468465, "r_engine_stats": { "pages_accessed": 104 }, "filtered": 100, "r_filtered": 100, "using_index": true } }, { "table": { "table_name": "action", "access_type": "ref", "possible_keys": [ "IDX_action_user_id", "IDX_action_au_r_c_u_d", "IDX_action_r_u_d" ], "key": "IDX_action_r_u_d", "key_length": "19", "used_key_parts": ["repo_id", "user_id", "is_deleted"], "ref": ["gitea.repository.id", "const", "const"], "r_loops": 51, "rows": 129, "r_rows": 507.8627451, "r_table_time_ms": 15852.30487, "r_other_time_ms": 13.85372599, "r_engine_stats": { "pages_accessed": 77944, "pages_read_count": 9094, "pages_read_time_ms": 53190293.67 }, "filtered": 100, "r_filtered": 3.899463341, "attached_condition": "`action`.act_user_id = 1 and `action`.is_private = 0" } } ], "subqueries": [ { "query_block": { "select_id": 4, "r_loops": 1, "r_total_time_ms": 0.055215297, "nested_loop": [ { "table": { "table_name": "user", "access_type": "ALL", "possible_keys": ["PRIMARY"], "r_loops": 1, "rows": 31, "r_rows": 31, "r_table_time_ms": 0.028239505, "r_other_time_ms": 0.019582574, "r_engine_stats": { "pages_accessed": 1 }, "filtered": 100, "r_filtered": 87.09677419, "attached_condition": "`user`.`type` = 0 and `user`.visibility in (0,2)" } } ] } } ] } } } } ```
3. Statement ```json { "query_optimization": { "r_total_time_ms": 0.382885099 }, "query_block": { "select_id": 1, "r_loops": 1, "r_total_time_ms": 15281.56887, "nested_loop": [ { "table": { "table_name": "user", "access_type": "const", "possible_keys": ["PRIMARY"], "key": "PRIMARY", "key_length": "8", "used_key_parts": ["id"], "ref": ["const"], "r_loops": 0, "rows": 1, "r_rows": null, "r_engine_stats": { "pages_accessed": 1 }, "filtered": 100, "r_filtered": null } }, { "table": { "table_name": "repository", "access_type": "ALL", "possible_keys": ["PRIMARY", "IDX_repository_is_private"], "r_loops": 1, "rows": 101, "r_rows": 101, "r_table_time_ms": 0.149008663, "r_other_time_ms": 0.449722574, "r_engine_stats": { "pages_accessed": 4 }, "filtered": 66.33663177, "r_filtered": 50.4950495, "attached_condition": "repository.is_private = 0 and !(repository.owner_id,repository.owner_id in (subquery#4))" } }, { "table": { "table_name": "repository", "access_type": "eq_ref", "possible_keys": ["PRIMARY"], "key": "PRIMARY", "key_length": "8", "used_key_parts": ["id"], "ref": ["gitea.repository.id"], "r_loops": 51, "rows": 1, "r_rows": 1, "r_table_time_ms": 0.315848614, "r_other_time_ms": 0.031174901, "r_engine_stats": { "pages_accessed": 104 }, "filtered": 100, "r_filtered": 100, "using_index": true } }, { "table": { "table_name": "action", "access_type": "ref", "possible_keys": [ "IDX_action_user_id", "IDX_action_au_r_c_u_d", "IDX_action_r_u_d" ], "key": "IDX_action_r_u_d", "key_length": "19", "used_key_parts": ["repo_id", "user_id", "is_deleted"], "ref": ["gitea.repository.id", "const", "const"], "r_loops": 51, "rows": 129, "r_rows": 507.8627451, "r_table_time_ms": 15273.24721, "r_other_time_ms": 7.312031735, "r_engine_stats": { "pages_accessed": 77933, "pages_read_count": 8640, "pages_read_time_ms": 51436849.48 }, "filtered": 100, "r_filtered": 3.899463341, "attached_condition": "`action`.act_user_id = 1 and `action`.is_private = 0" } } ], "subqueries": [ { "query_block": { "select_id": 4, "r_loops": 1, "r_total_time_ms": 0.049603218, "nested_loop": [ { "table": { "table_name": "user", "access_type": "ALL", "possible_keys": ["PRIMARY"], "r_loops": 1, "rows": 31, "r_rows": 31, "r_table_time_ms": 0.025692178, "r_other_time_ms": 0.020458218, "r_engine_stats": { "pages_accessed": 1 }, "filtered": 100, "r_filtered": 83.87096774, "attached_condition": "`user`.`type` = 0 and `user`.visibility in (0,1)" } } ] } } ] } } ```
Keys in the action table ![image](https://github.com/user-attachments/assets/c1967c46-87c6-4975-bbf5-4bb4bd8e4902)
KimonHoffmann commented 1 day ago

We're running a relatively small instance in Docker, backed by SQLite and are also observing periodic, extremely long delays for quite some time (I don't remember the exact version, but I do remember it was the one where the GoGit was replaced in favor of the git binary, which is why back then I chalked the added delay up to further optimizations being necessary in interacting with the git binary).

Having enabled trace logging now, on 1.22.2 I can confirm the pattern observed by others above.

Please note that the following log entries are complete and have only been annotated with comments and anonymized. They implicitly show that while this is going on the whole instance is blocked, as indicated by the upload-pack pack requests suffering as a result of this. What is common is that there always is a Dashboard request in the mix, either explicitly in the form of a GET / request, or implicitly in the form of a GET /user/login request, which appear to be the requests actually causing the delays/slowdowns.

# Client A reported to be slow
Sep 13 10:08:14 ANONYMIZED docker[3878067]: 2024/09/13 08:08:14 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for AAA.AAA.AAA.AAA:35204, elapsed 3469.3ms @ web/web.go:118(web.Routes.webAuth)
# Client B reported to be slow
Sep 13 10:08:15 ANONYMIZED docker[3878067]: 2024/09/13 08:08:15 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for BBB.BBB.BBB.BBB:58500, elapsed 3875.2ms @ web/web.go:118(web.Routes.webAuth)
# Client C reported to be slow
Sep 13 10:08:15 ANONYMIZED docker[3878067]: 2024/09/13 08:08:15 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for CCC.CCC.CCC.CCC:53622, elapsed 3875.5ms @ web/web.go:118(web.Routes.webAuth)
# Client D reported to be slow
Sep 13 10:08:42 ANONYMIZED docker[3878067]: 2024/09/13 08:08:42 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /user/login for DDD.DDD.DDD.DDD:40112, elapsed 3260.5ms @ auth/auth.go:164(auth.SignIn)
# Client E reported to be slow
Sep 13 10:08:43 ANONYMIZED docker[3878067]: 2024/09/13 08:08:43 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for EEE.EEE.EEE.EEE:60660, elapsed 3516.4ms @ web/web.go:118(web.Routes.webAuth)
# Client F reported to be slow
Sep 13 10:08:44 ANONYMIZED docker[3878067]: 2024/09/13 08:08:44 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for FFF.FFF.FFF.FFF:43522, elapsed 3770.4ms @ web/web.go:118(web.Routes.webAuth)
# Client G reported to be slow
Sep 13 10:08:44 ANONYMIZED docker[3878067]: 2024/09/13 08:08:44 ...eb/routing/logger.go:68:func1() [W] router: slow      GET /ANONYMIZED.git/info/refs?service=git-upload-pack for GGG.GGG.GGG.GGG:33844, elapsed 3770.4ms @ web/web.go:118(web.Routes.webAuth)

# Multiple reports of slow SQL queries
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 37.408652439s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 37.40420057s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 37.40442079s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...ers/web/auth/auth.go:56:autoSignIn() [W] [Slow SQL Query] DELETE FROM `auth_token` WHERE expires_unix<? [1726214920] - 9.408882468s

# Client D's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /user/login for DDD.DDD.DDD.DDD:40112, 200 OK in 9793.4ms @ auth/auth.go:164(auth.SignIn)

# Multiple reports of slow SQL queries
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 8.372552405s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 8.372577691s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...ties/notification.go:296:GetUIDsAndNotificationCounts() [W] [Slow SQL Query] SELECT user_id, sum(case when status= ? then 1 else 0 end) AS count FROM notification WHERE user_id IN (SELECT user_id FROM notification WHERE updated_unix >= ? AND updated_unix < ?) GROUP BY user_id [1 1726214886 1726214896] - 31.028956563s
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...auth/access_token.go:174:GetAccessTokenBySHA() [W] [Slow SQL Query] SELECT `id`, `uid`, `name`, `token_hash`, `token_salt`, `token_last_eight`, `scope`, `created_unix`, `updated_unix` FROM `access_token` WHERE (token_last_eight = ?) [d4b41293] - 9.120132387s

# Client A's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for AAA.AAA.AAA.AAA:35204, 200 OK in 38096.4ms @ repo/githttp.go:517(repo.GetInfoRefs)
# Client E's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for EEE.EEE.EEE.EEE:60660, 200 OK in 9143.2ms @ repo/githttp.go:517(repo.GetInfoRefs)
# Client F's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for FFF.FFF.FFF.FFF:43522, 200 OK in 8396.9ms @ repo/githttp.go:517(repo.GetInfoRefs)
# Client C's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for CCC.CCC.CCC.CCC:53622, 200 OK in 37502.3ms @ repo/githttp.go:517(repo.GetInfoRefs)
# Client B's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for BBB.BBB.BBB.BBB:58500, 200 OK in 37506.9ms @ repo/githttp.go:517(repo.GetInfoRefs)
# Client G's request completes
Sep 13 10:08:49 ANONYMIZED docker[3878067]: 2024/09/13 08:08:49 ...eb/routing/logger.go:102:func1() [I] router: completed GET /ANONYMIZED.git/info/refs?service=git-upload-pack for GGG.GGG.GGG.GGG:33844, 200 OK in 8402.5ms @ repo/githttp.go:517(repo.GetInfoRefs)

# Followed by a slew of these
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:134:GetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}
Sep 13 10:08:51 ANONYMIZED docker[3878067]: 2024/09/13 08:08:51 ...les/cache/context.go:147:SetContextData() [W] cache context is expired, may be misused for long-life tasks: &{map[] {{0 0} 0 0 {{} 0} {{} 0}} {13956965971883172490 69352623855275 0x69a7300} false}