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.

[zeripath]

I mean you could try:

CREATE INDEX ON action (created_unix DESC)

---

However, I note that even your no ORDER BY query still isn't using an index.

[somera]

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.

The problem is order by ...

Here the plan without this: https://explain.depesz.com/s/ygq3

[somera]

giteadb=# \d action
                                          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)
    "action_created_unix_idx" btree (created_unix DESC)
    "action_user_id_idx" btree (user_id)

Looks better now (~600ms faster for the start page)

https://explain.depesz.com/s/K6u3

[somera]

I remved

"action_user_id_idx" btree (user_id)

now.

[zeripath]

What the hell is going on:

"Limit  (cost=0.71..19.21 rows=20 width=456) (actual time=0.088..0.371 rows=20 loops=1)"
"  ->  Nested Loop  (cost=0.71..604060.66 rows=653278 width=456) (actual time=0.085..0.358 rows=20 loops=1)"
"        ->  Index Scan using action_created_unix_idx on action  (cost=0.43..404005.15 rows=653278 width=456) (actual time=0.053..0.120 rows=20 loops=1)"
"              Filter: ((NOT is_deleted) AND (user_id = 1))"
"              Rows Removed by Filter: 20"
"        ->  Index Only Scan using repository_pkey on repository  (cost=0.29..0.31 rows=1 width=8) (actual time=0.009..0.009 rows=1 loops=20)"
"              Index Cond: (id = action.repo_id)"
"              Heap Fetches: 20"
"Planning Time: 1.418 ms"
"Execution Time: 0.457 ms"

Why would your db choose to use the index action_created_unix_idx!!

[somera]

I don't know. ;)

My action table has 1.307.514 entries.

[zeripath]

Maybe you'd benefit from:

CREATE INDEX IDX_action_c_u_d ON action (created_unix DESC, user_id, is_deleted)

Possibly even append an INCLUDE (repo_id) there.

[somera]

Maybe you'd benefit from:

CREATE INDEX IDX_action_c_u_d ON action (created_unix DESC, user_id, is_deleted)

Possibly even append an INCLUDE (repo_id) there.

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)
    "idx_action_c_u_d" btree (created_unix DESC, user_id, is_deleted)

https://explain.depesz.com/s/YJuyr

The start page feels better.

[zeripath]

Is that fast enough now?

[somera]

Is that fast enough now?

Yes! Thx.

[somera]

Should I remove the index

"idx_action_c_u_d" btree (created_unix DESC, user_id, is_deleted)

and wait for the fix release?

[zeripath]

OK, now Gitea won't start up with those indexes like that due to a bug in xorm - so we have two problems:

• We need to fix xorm to tolerate indexes that don't match the xorm pattern.
• I guess we need to add this index by default
  • One problem is that xorm can't express DESCing indexes so we should check if the DESC is necessary
  • Another is that I'm not sure how applicable this index is to smaller dbs

My large "test" db "only" has 42569 rows in action so I guess this is why I didn't see this.

Could you check if this is still fast:

CREATE INDEX action_c_u_d ON action (created_unix, user_id, is_deleted)

If so that will make fixing this easier.

[zeripath]

Yes you will need to remove the index or at least remove it in between restarts.

[zeripath]

OK here's the XORM fix: https://gitea.com/xorm/xorm/pulls/2174

Now actually I think we should not drop irregular indices as it is likely that the user has added these deliberately but I guess we should discuss that in another PR.

[zeripath]

@somera I've got a few more indexes to check:

CREATE "IDX_action_c_r_u_d" ON action (created_unix, repo_id, user_id, is_deleted)

and

CREATE "IDX_action_c_u_d_r" ON action (created_unix, user_id, is_deleted, repo_id)

If either of those are faster than IDX_action_c_u_d it would be helpful to know.

[somera]

OK, now Gitea won't start up with those indexes like that due to a bug in xorm - so we have two problems:

• We need to fix xorm to tolerate indexes that don't match the xorm pattern.

• I guess we need to add this index by default

  • One problem is that xorm can't express DESCing indexes so we should check if the DESC is necessary
  • Another is that I'm not sure how applicable this index is to smaller dbs

My large "test" db "only" has 42569 rows in action so I guess this is why I didn't see this.

Could you check if this is still fast:

CREATE INDEX action_c_u_d ON action (created_unix, user_id, is_deleted)

If so that will make fixing this easier.

Sorry, I didn't see the question.

Here the plan for the index: https://explain.depesz.com/s/JfF9

But the speed is same like with: CREATE INDEX IDX_action_c_u_d ON action (created_unix DESC, user_id, is_deleted)

[zeripath]

excellent so the DESC is unnecessary.

What about the repo_id containing ones?

[somera]

excellent so the DESC is unnecessary.

What about the repo_id containing ones?

You mean the user with only one repo?

Works too. Some ms slower.

The plan: https://explain.depesz.com/s/CfHx

[somera]

Workx now fine with 1.17.2