Start page: "slow" response time

[somera]

Description

This is not a bug. But I try to understand what gitea is doing.

I'm using my gitea for mirror external projects. Means, I have a lot of data. Now I see, that the start page need ~1 second for the first response. Gitea is running in local network.

If I open the gitea start page for user with only one project I see this:

And this result

is for user with a lot of projects.

This is the log for the longer run:

2022/09/02 16:59:14 models/user/user.go:996:GetUserByIDCtx() [I] [63121a42] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id"=$1 LIMIT 1 [1] - 1.754489ms
2022/09/02 16:59:14 .../issues/stopwatch.go:132:HasUserStopwatch() [I] [63121a42] [SQL] SELECT "id", "issue_id", "user_id", "created_unix" FROM "stopwatch" WHERE (user_id = $1) LIMIT 1 [1] - 831.954µs
2022/09/02 16:59:14 models/org.go:71:GetUserOrgsList() [I] [63121a42] [SQL] SELECT "user".id,"user".name,"user".full_name,"user".visibility,"user".avatar,"user".avatar_email,"user".use_custom_avatar, count(distinct repo_id) as org_count FROM "user" INNER JOIN "team" ON "team".org_id = "user".id INNER JOIN "team_user" ON "team".id = "team_user".team_id LEFT JOIN (SELECT id as repo_id, owner_id as repo_owner_id FROM repository WHERE ("repository".is_private=$1 AND "repository".owner_id NOT IN (SELECT id FROM "user" WHERE type=$2 AND visibility IN ($3))) OR "repository".id IN (SELECT repo_id FROM "access" WHERE "access".user_id=$4 AND "access".mode>$5) OR "repository".id IN (SELECT "team_repo".repo_id FROM team_repo INNER JOIN team_user ON "team_user".team_id = "team_repo".team_id WHERE "team_user".uid=$6) OR "repository".owner_id=$7 OR ("repository".is_private=$8 AND "repository".owner_id IN (SELECT "org_user".org_id FROM org_user WHERE "org_user".uid=$9))) "repository" ON "repository".repo_owner_id = "team".org_id WHERE ("team_user".uid = $10) GROUP BY "user".id,"user".name,"user".full_name,"user".visibility,"user".avatar,"user".avatar_email,"user".use_custom_avatar ORDER BY "user"."name" ASC [false 1 private 1 0 1 1 false 1 1] - 56.467784ms
2022/09/02 16:59:14 ...ers/web/user/home.go:79:Dashboard() [I] [63121a42] [SQL] SELECT count(*) FROM "org_user" WHERE (uid=$1) [1] - 1.239558ms
2022/09/02 16:59:14 ...dels/user_heatmap.go:71:getUserHeatmapData() [I] [63121a42] [SQL] SELECT created_unix / 900 * 900 AS timestamp, count(user_id) as contributions FROM "action" WHERE user_id=$1 AND act_user_id=$2 AND (created_unix > $3) GROUP BY timestamp ORDER BY timestamp [1 1 1630594754] - 1.663216ms
2022/09/02 16:59:14 ...odels/repo/mirror.go:174:GetUserMirrorRepositories() [I] [63121a42] [SQL] SELECT "id", "owner_id", "owner_name", "lower_name", "name", "description", "website", "original_service_type", "original_url", "default_branch", "num_watches", "num_stars", "num_forks", "num_issues", "num_closed_issues", "num_pulls", "num_closed_pulls", "num_milestones", "num_closed_milestones", "num_projects", "num_closed_projects", "is_private", "is_empty", "is_archived", "is_mirror", "status", "is_fork", "fork_id", "is_template", "template_id", "size", "is_fsck_enabled", "close_issues_via_commit_in_any_branch", "topics", "trust_model", "avatar", "created_unix", "updated_unix" FROM "repository" WHERE (owner_id = $1) AND (is_mirror = $2) [1 true] - 721.573µs
2022/09/02 16:59:14 ...odels/repo/mirror.go:146:loadAttributes() [I] [63121a42] [SQL] SELECT "id", "repo_id", "interval", "enable_prune", "updated_unix", "next_update_unix", "lfs_enabled", "lfs_endpoint" FROM "mirror" WHERE (id > 0) AND "repo_id" IN ($1,$2) [13734 13735] - 463.139µs
2022/09/02 16:59:15 models/action.go:364:GetFeeds() [I] [63121a42] [SQL] SELECT "action".* FROM "action" INNER JOIN "repository" ON "repository".id = "action".repo_id WHERE user_id=$1 AND is_deleted=$2 ORDER BY "action"."created_unix" DESC LIMIT 20 [1 false] - 586.989343ms
2022/09/02 16:59:15 ...odels/action_list.go:39:loadUsers() [I] [63121a42] [SQL] SELECT "id", "lower_name", "name", "full_name", "email", "keep_email_private", "email_notifications_preference", "passwd", "passwd_hash_algo", "must_change_password", "login_type", "login_source", "login_name", "type", "location", "website", "rands", "salt", "language", "description", "created_unix", "updated_unix", "last_login_unix", "last_repo_visibility", "max_repo_creation", "is_active", "is_admin", "is_restricted", "allow_git_hook", "allow_import_local", "allow_create_organization", "prohibit_login", "avatar", "avatar_email", "use_custom_avatar", "num_followers", "num_following", "num_stars", "num_repos", "num_teams", "num_members", "visibility", "repo_admin_change_team_access", "diff_view_style", "theme", "keep_activity_private" FROM "user" WHERE "id" IN ($1,$2,$3,$4) [2039 2040 2042 156] - 718.559µs

This

2022/09/02 16:59:15 models/action.go:364:GetFeeds() [I] [63121a42] [SQL] SELECT "action".* FROM "action" INNER JOIN "repository" ON "repository".id = "action".repo_id WHERE user_id=$1 AND is_deleted=$2 ORDER BY "action"."created_unix" DESC LIMIT 20 [1 false] - 586.989343ms

query is the trigger for the slowdown. And this https://explain.depesz.com/s/BEHk#html is the plan for the query on my instance.

My questions:

• Why is gitea exuting this query fot the start page?
• More data = longer loading time for the gitea startpage?

Gitea Version

1.17.1

Can you reproduce the bug on the Gitea demo site?

No

Log Gist

No response

Screenshots

No response

Git Version

2.25.1

Operating System

Ubuntu 20.04.4

How are you running Gitea?

Self hosted gitea-1.17.1-linux-amd64

Database

PostgreSQL

[somera]

Answer for the first question: "Why is gitea exuting this query fot the start page?" -> this will be shown on the start page. Last 20 actions.

[zeripath]

This is strange because it indicates that the indices are not being used correctly. The plan should look like:

                                               QUERY PLAN                                                
---------------------------------------------------------------------------------------------------------
 Limit  (cost=57.14..57.15 rows=5 width=393)
   ->  Sort  (cost=57.14..57.15 rows=5 width=393)
         Sort Key: action.created_unix DESC
         ->  Nested Loop  (cost=0.57..57.08 rows=5 width=393)
               ->  Index Scan using "IDX_action_user_id" on action  (cost=0.29..15.58 rows=5 width=393)
                     Index Cond: (user_id = 18059)
                     Filter: (NOT is_deleted)
               ->  Index Only Scan using repository_pkey on repository  (cost=0.28..8.30 rows=1 width=8)
                     Index Cond: (id = action.repo_id)
(9 rows)

What is the result of \d action on the psql console?

It should look something like:

                                      Table "public.action"
    Column    |          Type          | Collation | Nullable |              Default               
--------------+------------------------+-----------+----------+------------------------------------
 id           | bigint                 |           | not null | nextval('action_id_seq'::regclass)
 user_id      | bigint                 |           |          | 
 op_type      | integer                |           |          | 
 act_user_id  | bigint                 |           |          | 
 repo_id      | bigint                 |           |          | 
 comment_id   | bigint                 |           |          | 
 is_deleted   | boolean                |           | not null | false
 ref_name     | character varying(255) |           |          | 
 is_private   | boolean                |           | not null | false
 content      | text                   |           |          | 
 created_unix | bigint                 |           |          | 
Indexes:
    "action_pkey" PRIMARY KEY, btree (id)
    "IDX_action_act_user_id" btree (act_user_id)
    "IDX_action_au_r_c_u_d" btree (act_user_id, repo_id, created_unix, user_id, is_deleted)
    "IDX_action_comment_id" btree (comment_id)
    "IDX_action_created_unix" btree (created_unix)
    "IDX_action_is_deleted" btree (is_deleted)
    "IDX_action_is_private" btree (is_private)
    "IDX_action_r_u_d" btree (repo_id, user_id, is_deleted)
    "IDX_action_repo_id" btree (repo_id)
    "IDX_action_user_id" btree (user_id)

[somera]

I'm using this

PostgreSQL 13.8 (Ubuntu 13.8-1.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit

[somera]

                                          Tabelle »public.action«
    Spalte    |          Typ           | Sortierfolge | NULL erlaubt? |            Vorgabewert
--------------+------------------------+--------------+---------------+------------------------------------
 id           | bigint                 |              | not null      | nextval('action_id_seq'::regclass)
 user_id      | bigint                 |              |               |
 op_type      | integer                |              |               |
 act_user_id  | bigint                 |              |               |
 repo_id      | bigint                 |              |               |
 comment_id   | bigint                 |              |               |
 is_deleted   | boolean                |              | not null      | false
 ref_name     | character varying(255) |              |               |
 is_private   | boolean                |              | not null      | false
 content      | text                   |              |               |
 created_unix | bigint                 |              |               |
Indexe:
    "action_pkey" PRIMARY KEY, btree (id)
    "IDX_action_au_r_c_u_d" btree (act_user_id, repo_id, created_unix, user_id, is_deleted)
    "IDX_action_comment_id" btree (comment_id)
    "IDX_action_r_u_d" btree (repo_id, user_id, is_deleted)

[zeripath]

Ah... I've just seen that there are some "legacy" indices in my example above. I've just got the same schema as you and found the following query plan:

 tc5=# explain select action.* from action inner join "repository" ON "repository".id = "action".repo_id WHERE user_id=18059 AND is_deleted=false ORDER BY "action"."created_unix" DESC LIMIT 20
;
                                               QUERY PLAN                                                
---------------------------------------------------------------------------------------------------------
 Limit  (cost=1677.66..1677.67 rows=5 width=393)
   ->  Sort  (cost=1677.66..1677.67 rows=5 width=393)
         Sort Key: action.created_unix DESC
         ->  Nested Loop  (cost=0.57..1677.60 rows=5 width=393)
               ->  Index Scan using "IDX_action_r_u_d" on action  (cost=0.29..1636.10 rows=5 width=393)
                     Index Cond: ((user_id = 18059) AND (is_deleted = false))
               ->  Index Only Scan using repository_pkey on repository  (cost=0.28..8.30 rows=1 width=8)
                     Index Cond: (id = action.repo_id)
(8 rows)

EDIT: I'd put up the wrong plan this is the right one

[zeripath]

Damn I suspect this means that postgres needs different indices to that of MySQL and other DBs and I was led down the garden path by my previous testing with old indices present.

OK I guess we just need to twiddle with the indices until we find the quickest for this.

[somera]

Damn I suspect this means that postgres needs different indices to that of MySQL and other DBs and I was led down the garden path by my previous testing with old indices present.

OK I guess we just need to twiddle with the indices until we find the quickest for this.

Ok. Sounds good.

[zeripath]

Could you compare which is faster between doing:

CREATE INDEX ON action (user_id, is_deleted)

And:

CREATE INDEX ON action (user_id)

?

[somera]

Not faster.

https://explain.depesz.com/s/6vv0

[zeripath]

That's very weird because it should be using the index - which your explain does not show. Certainly it works for me.

You will likely need to drop those new indexes before restarting Gitea btw - (I've just discovered that there is a bug in xorm related to its schema reading.)

[zeripath]

What version of postgres are you running?

[somera]

Added CREATE INDEX ON action (user_id, is_deleted) -> https://explain.depesz.com/s/bqTF

Added CREATE INDEX ON action (user_id) -> https://explain.depesz.com/s/tJisn

Removed CREATE INDEX ON action (user_id, is_deleted) -> https://explain.depesz.com/s/oVKH

[somera]

I'm using this

PostgreSQL 13.8 (Ubuntu 13.8-1.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, 64-bit

@zeripath here my PG Version.

[zeripath]

I just don't understand why it isn't using any of the indices.

I mean this is the plan I get with the user_id and is_deleted index:

;
                                                   QUERY PLAN                                           >
-------------------------------------------------------------------------------------------------------->
 Limit  (cost=61.00..61.02 rows=5 width=393)
   ->  Sort  (cost=61.00..61.02 rows=5 width=393)
         Sort Key: action.created_unix DESC
         ->  Nested Loop  (cost=0.57..60.94 rows=5 width=393)
               ->  Index Scan using action_user_id_is_deleted_idx on action  (cost=0.29..19.44 rows=5 wi>
                     Index Cond: ((user_id = 18059) AND (is_deleted = false))
               ->  Index Only Scan using repository_pkey on repository  (cost=0.28..8.30 rows=1 width=8)
                     Index Cond: (id = action.repo_id)
(8 rows)

It just makes no sense to me that it would not use the index. That's why we have an index. Even the "IDX_action_r_u_d" btree (repo_id, user_id, is_deleted) should have been enough.