forgejo/models/db/engine_test.go

126 lines
3.5 KiB
Go
Raw Normal View History

// Copyright 2019 The Gitea Authors. All rights reserved.
// SPDX-License-Identifier: MIT
package db_test
import (
"path/filepath"
"testing"
[GITEA] Add slow SQL query warning - Databases are one of the most important parts of Forgejo, every interaction with Forgejo uses the database in one way or another. Therefore, it is important to maintain the database and recognize when Forgejo is not doing well with the database. Forgejo already has the option to log *every* SQL query along with its execution time, but monitoring becomes impractical for larger instances and takes up unnecessary storage in the logs. - Add a QoL enhancement that allows instance administrators to specify a threshold value beyond which query execution time is logged as a warning in the xorm logger. The default value is a conservative five seconds to avoid this becoming a source of spam in the logs. - The use case for this patch is that with an instance the size of Codeberg, monitoring SQL logs is not very fruitful and most of them are uninteresting. Recently, in the context of persistent deadlock issues (https://codeberg.org/forgejo/forgejo/issues/220), I have noticed that certain queries hold locks on tables like comment and issue for several seconds. This patch helps to identify which queries these are and when they happen. - Added unit test. (cherry picked from commit 24bbe7886fb4cb9a38c8dab8c44f4c9cbfa25481) (cherry picked from commit 6e29145b3c1455498531593d38e6a914941a12cb) (cherry picked from commit 63731e30712872bd2395eb3cf36d9996e5793645) (cherry picked from commit 3ce1a097369c132654de70df707b867e47bd1c40) (cherry picked from commit a64426907de788cc0937a7a2b16af4d2f26f7fe6) (cherry picked from commit 4b1921569156445c58d9889602733da5934c7b95) (cherry picked from commit e6356744359fa947c049827d60c2ea0e277e03dc) (cherry picked from commit 9cf501f1af4cd870221cef6af489618785b71186) (cherry picked from commit 0d6b934eba1c0e9b27b364791113aae816b6b366) (cherry picked from commit 4b6c2738795002887844a106f2fed2ef1673eed1) (cherry picked from commit b50517139cc62f214c1629ef2fd9bcaa37b46202) (cherry picked from commit 6546dd1fc946e620a02b6d1afed7d5ac50655fa8) (cherry picked from commit 3eda6890e6b840237f675a2873c102a6fc86b8f1) [GITEA] Add slow SQL query warning (squash) document the setting (cherry picked from commit ce38599c5141c7fc6bc054819f5ff1c1b45bda1f) (cherry picked from commit 794aa67c68c8e24ac7301eb7ef767c6e2499a78d) (cherry picked from commit 8227673deb1b93015f56e446b27c52a0013eba29) (cherry picked from commit 8854d1d4dda72304f43ea8aa61a941701a5deede) (cherry picked from commit 9121a0e21f7c5de89ba2d8afa9054c5fbf210fb1) (cherry picked from commit 41bae2e42506e7db1d2b5e0af28ed3ac1f5d5713)
2023-08-18 04:39:23 +02:00
"time"
"code.gitea.io/gitea/models/db"
issues_model "code.gitea.io/gitea/models/issues"
"code.gitea.io/gitea/models/unittest"
[GITEA] Add slow SQL query warning - Databases are one of the most important parts of Forgejo, every interaction with Forgejo uses the database in one way or another. Therefore, it is important to maintain the database and recognize when Forgejo is not doing well with the database. Forgejo already has the option to log *every* SQL query along with its execution time, but monitoring becomes impractical for larger instances and takes up unnecessary storage in the logs. - Add a QoL enhancement that allows instance administrators to specify a threshold value beyond which query execution time is logged as a warning in the xorm logger. The default value is a conservative five seconds to avoid this becoming a source of spam in the logs. - The use case for this patch is that with an instance the size of Codeberg, monitoring SQL logs is not very fruitful and most of them are uninteresting. Recently, in the context of persistent deadlock issues (https://codeberg.org/forgejo/forgejo/issues/220), I have noticed that certain queries hold locks on tables like comment and issue for several seconds. This patch helps to identify which queries these are and when they happen. - Added unit test. (cherry picked from commit 24bbe7886fb4cb9a38c8dab8c44f4c9cbfa25481) (cherry picked from commit 6e29145b3c1455498531593d38e6a914941a12cb) (cherry picked from commit 63731e30712872bd2395eb3cf36d9996e5793645) (cherry picked from commit 3ce1a097369c132654de70df707b867e47bd1c40) (cherry picked from commit a64426907de788cc0937a7a2b16af4d2f26f7fe6) (cherry picked from commit 4b1921569156445c58d9889602733da5934c7b95) (cherry picked from commit e6356744359fa947c049827d60c2ea0e277e03dc) (cherry picked from commit 9cf501f1af4cd870221cef6af489618785b71186) (cherry picked from commit 0d6b934eba1c0e9b27b364791113aae816b6b366) (cherry picked from commit 4b6c2738795002887844a106f2fed2ef1673eed1) (cherry picked from commit b50517139cc62f214c1629ef2fd9bcaa37b46202) (cherry picked from commit 6546dd1fc946e620a02b6d1afed7d5ac50655fa8) (cherry picked from commit 3eda6890e6b840237f675a2873c102a6fc86b8f1) [GITEA] Add slow SQL query warning (squash) document the setting (cherry picked from commit ce38599c5141c7fc6bc054819f5ff1c1b45bda1f) (cherry picked from commit 794aa67c68c8e24ac7301eb7ef767c6e2499a78d) (cherry picked from commit 8227673deb1b93015f56e446b27c52a0013eba29) (cherry picked from commit 8854d1d4dda72304f43ea8aa61a941701a5deede) (cherry picked from commit 9121a0e21f7c5de89ba2d8afa9054c5fbf210fb1) (cherry picked from commit 41bae2e42506e7db1d2b5e0af28ed3ac1f5d5713)
2023-08-18 04:39:23 +02:00
"code.gitea.io/gitea/modules/log"
"code.gitea.io/gitea/modules/setting"
[GITEA] Add slow SQL query warning - Databases are one of the most important parts of Forgejo, every interaction with Forgejo uses the database in one way or another. Therefore, it is important to maintain the database and recognize when Forgejo is not doing well with the database. Forgejo already has the option to log *every* SQL query along with its execution time, but monitoring becomes impractical for larger instances and takes up unnecessary storage in the logs. - Add a QoL enhancement that allows instance administrators to specify a threshold value beyond which query execution time is logged as a warning in the xorm logger. The default value is a conservative five seconds to avoid this becoming a source of spam in the logs. - The use case for this patch is that with an instance the size of Codeberg, monitoring SQL logs is not very fruitful and most of them are uninteresting. Recently, in the context of persistent deadlock issues (https://codeberg.org/forgejo/forgejo/issues/220), I have noticed that certain queries hold locks on tables like comment and issue for several seconds. This patch helps to identify which queries these are and when they happen. - Added unit test. (cherry picked from commit 24bbe7886fb4cb9a38c8dab8c44f4c9cbfa25481) (cherry picked from commit 6e29145b3c1455498531593d38e6a914941a12cb) (cherry picked from commit 63731e30712872bd2395eb3cf36d9996e5793645) (cherry picked from commit 3ce1a097369c132654de70df707b867e47bd1c40) (cherry picked from commit a64426907de788cc0937a7a2b16af4d2f26f7fe6) (cherry picked from commit 4b1921569156445c58d9889602733da5934c7b95) (cherry picked from commit e6356744359fa947c049827d60c2ea0e277e03dc) (cherry picked from commit 9cf501f1af4cd870221cef6af489618785b71186) (cherry picked from commit 0d6b934eba1c0e9b27b364791113aae816b6b366) (cherry picked from commit 4b6c2738795002887844a106f2fed2ef1673eed1) (cherry picked from commit b50517139cc62f214c1629ef2fd9bcaa37b46202) (cherry picked from commit 6546dd1fc946e620a02b6d1afed7d5ac50655fa8) (cherry picked from commit 3eda6890e6b840237f675a2873c102a6fc86b8f1) [GITEA] Add slow SQL query warning (squash) document the setting (cherry picked from commit ce38599c5141c7fc6bc054819f5ff1c1b45bda1f) (cherry picked from commit 794aa67c68c8e24ac7301eb7ef767c6e2499a78d) (cherry picked from commit 8227673deb1b93015f56e446b27c52a0013eba29) (cherry picked from commit 8854d1d4dda72304f43ea8aa61a941701a5deede) (cherry picked from commit 9121a0e21f7c5de89ba2d8afa9054c5fbf210fb1) (cherry picked from commit 41bae2e42506e7db1d2b5e0af28ed3ac1f5d5713)
2023-08-18 04:39:23 +02:00
"code.gitea.io/gitea/modules/test"
_ "code.gitea.io/gitea/cmd" // for TestPrimaryKeys
"github.com/stretchr/testify/assert"
[GITEA] Add slow SQL query warning - Databases are one of the most important parts of Forgejo, every interaction with Forgejo uses the database in one way or another. Therefore, it is important to maintain the database and recognize when Forgejo is not doing well with the database. Forgejo already has the option to log *every* SQL query along with its execution time, but monitoring becomes impractical for larger instances and takes up unnecessary storage in the logs. - Add a QoL enhancement that allows instance administrators to specify a threshold value beyond which query execution time is logged as a warning in the xorm logger. The default value is a conservative five seconds to avoid this becoming a source of spam in the logs. - The use case for this patch is that with an instance the size of Codeberg, monitoring SQL logs is not very fruitful and most of them are uninteresting. Recently, in the context of persistent deadlock issues (https://codeberg.org/forgejo/forgejo/issues/220), I have noticed that certain queries hold locks on tables like comment and issue for several seconds. This patch helps to identify which queries these are and when they happen. - Added unit test. (cherry picked from commit 24bbe7886fb4cb9a38c8dab8c44f4c9cbfa25481) (cherry picked from commit 6e29145b3c1455498531593d38e6a914941a12cb) (cherry picked from commit 63731e30712872bd2395eb3cf36d9996e5793645) (cherry picked from commit 3ce1a097369c132654de70df707b867e47bd1c40) (cherry picked from commit a64426907de788cc0937a7a2b16af4d2f26f7fe6) (cherry picked from commit 4b1921569156445c58d9889602733da5934c7b95) (cherry picked from commit e6356744359fa947c049827d60c2ea0e277e03dc) (cherry picked from commit 9cf501f1af4cd870221cef6af489618785b71186) (cherry picked from commit 0d6b934eba1c0e9b27b364791113aae816b6b366) (cherry picked from commit 4b6c2738795002887844a106f2fed2ef1673eed1) (cherry picked from commit b50517139cc62f214c1629ef2fd9bcaa37b46202) (cherry picked from commit 6546dd1fc946e620a02b6d1afed7d5ac50655fa8) (cherry picked from commit 3eda6890e6b840237f675a2873c102a6fc86b8f1) [GITEA] Add slow SQL query warning (squash) document the setting (cherry picked from commit ce38599c5141c7fc6bc054819f5ff1c1b45bda1f) (cherry picked from commit 794aa67c68c8e24ac7301eb7ef767c6e2499a78d) (cherry picked from commit 8227673deb1b93015f56e446b27c52a0013eba29) (cherry picked from commit 8854d1d4dda72304f43ea8aa61a941701a5deede) (cherry picked from commit 9121a0e21f7c5de89ba2d8afa9054c5fbf210fb1) (cherry picked from commit 41bae2e42506e7db1d2b5e0af28ed3ac1f5d5713)
2023-08-18 04:39:23 +02:00
"xorm.io/xorm"
)
func TestDumpDatabase(t *testing.T) {
assert.NoError(t, unittest.PrepareTestDatabase())
dir := t.TempDir()
type Version struct {
ID int64 `xorm:"pk autoincr"`
Version int64
}
assert.NoError(t, db.GetEngine(db.DefaultContext).Sync(new(Version)))
for _, dbType := range setting.SupportedDatabaseTypes {
assert.NoError(t, db.DumpDatabase(filepath.Join(dir, dbType+".sql"), dbType))
}
}
func TestDeleteOrphanedObjects(t *testing.T) {
assert.NoError(t, unittest.PrepareTestDatabase())
countBefore, err := db.GetEngine(db.DefaultContext).Count(&issues_model.PullRequest{})
assert.NoError(t, err)
_, err = db.GetEngine(db.DefaultContext).Insert(&issues_model.PullRequest{IssueID: 1000}, &issues_model.PullRequest{IssueID: 1001}, &issues_model.PullRequest{IssueID: 1003})
assert.NoError(t, err)
orphaned, err := db.CountOrphanedObjects(db.DefaultContext, "pull_request", "issue", "pull_request.issue_id=issue.id")
assert.NoError(t, err)
assert.EqualValues(t, 3, orphaned)
err = db.DeleteOrphanedObjects(db.DefaultContext, "pull_request", "issue", "pull_request.issue_id=issue.id")
assert.NoError(t, err)
countAfter, err := db.GetEngine(db.DefaultContext).Count(&issues_model.PullRequest{})
assert.NoError(t, err)
assert.EqualValues(t, countBefore, countAfter)
}
func TestPrimaryKeys(t *testing.T) {
// Some dbs require that all tables have primary keys, see
// https://github.com/go-gitea/gitea/issues/21086
// https://github.com/go-gitea/gitea/issues/16802
// To avoid creating tables without primary key again, this test will check them.
// Import "code.gitea.io/gitea/cmd" to make sure each db.RegisterModel in init functions has been called.
beans, err := db.NamesToBean()
if err != nil {
t.Fatal(err)
}
whitelist := map[string]string{
"the_table_name_to_skip_checking": "Write a note here to explain why",
"forgejo_sem_ver": "seriously dude",
}
for _, bean := range beans {
table, err := db.TableInfo(bean)
if err != nil {
t.Fatal(err)
}
if why, ok := whitelist[table.Name]; ok {
t.Logf("ignore %q because %q", table.Name, why)
continue
}
if len(table.PrimaryKeys) == 0 {
t.Errorf("table %q has no primary key", table.Name)
}
}
}
[GITEA] Add slow SQL query warning - Databases are one of the most important parts of Forgejo, every interaction with Forgejo uses the database in one way or another. Therefore, it is important to maintain the database and recognize when Forgejo is not doing well with the database. Forgejo already has the option to log *every* SQL query along with its execution time, but monitoring becomes impractical for larger instances and takes up unnecessary storage in the logs. - Add a QoL enhancement that allows instance administrators to specify a threshold value beyond which query execution time is logged as a warning in the xorm logger. The default value is a conservative five seconds to avoid this becoming a source of spam in the logs. - The use case for this patch is that with an instance the size of Codeberg, monitoring SQL logs is not very fruitful and most of them are uninteresting. Recently, in the context of persistent deadlock issues (https://codeberg.org/forgejo/forgejo/issues/220), I have noticed that certain queries hold locks on tables like comment and issue for several seconds. This patch helps to identify which queries these are and when they happen. - Added unit test. (cherry picked from commit 24bbe7886fb4cb9a38c8dab8c44f4c9cbfa25481) (cherry picked from commit 6e29145b3c1455498531593d38e6a914941a12cb) (cherry picked from commit 63731e30712872bd2395eb3cf36d9996e5793645) (cherry picked from commit 3ce1a097369c132654de70df707b867e47bd1c40) (cherry picked from commit a64426907de788cc0937a7a2b16af4d2f26f7fe6) (cherry picked from commit 4b1921569156445c58d9889602733da5934c7b95) (cherry picked from commit e6356744359fa947c049827d60c2ea0e277e03dc) (cherry picked from commit 9cf501f1af4cd870221cef6af489618785b71186) (cherry picked from commit 0d6b934eba1c0e9b27b364791113aae816b6b366) (cherry picked from commit 4b6c2738795002887844a106f2fed2ef1673eed1) (cherry picked from commit b50517139cc62f214c1629ef2fd9bcaa37b46202) (cherry picked from commit 6546dd1fc946e620a02b6d1afed7d5ac50655fa8) (cherry picked from commit 3eda6890e6b840237f675a2873c102a6fc86b8f1) [GITEA] Add slow SQL query warning (squash) document the setting (cherry picked from commit ce38599c5141c7fc6bc054819f5ff1c1b45bda1f) (cherry picked from commit 794aa67c68c8e24ac7301eb7ef767c6e2499a78d) (cherry picked from commit 8227673deb1b93015f56e446b27c52a0013eba29) (cherry picked from commit 8854d1d4dda72304f43ea8aa61a941701a5deede) (cherry picked from commit 9121a0e21f7c5de89ba2d8afa9054c5fbf210fb1) (cherry picked from commit 41bae2e42506e7db1d2b5e0af28ed3ac1f5d5713)
2023-08-18 04:39:23 +02:00
func TestSlowQuery(t *testing.T) {
lc, cleanup := test.NewLogChecker("slow-query")
lc.StopMark("[Slow SQL Query]")
defer cleanup()
e := db.GetEngine(db.DefaultContext)
engine, ok := e.(*xorm.Engine)
assert.True(t, ok)
// It's not possible to clean this up with XORM, but it's luckily not harmful
// to leave around.
engine.AddHook(&db.SlowQueryHook{
Treshold: time.Second * 10,
Logger: log.GetLogger("slow-query"),
})
// NOOP query.
e.Exec("SELECT 1 WHERE false;")
_, stopped := lc.Check(100 * time.Millisecond)
assert.False(t, stopped)
engine.AddHook(&db.SlowQueryHook{
Treshold: 0, // Every query should be logged.
Logger: log.GetLogger("slow-query"),
})
// NOOP query.
e.Exec("SELECT 1 WHERE false;")
_, stopped = lc.Check(100 * time.Millisecond)
assert.True(t, stopped)
}