[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 24bbe7886f)
(cherry picked from commit 6e29145b3c)
(cherry picked from commit 63731e3071)
(cherry picked from commit 3ce1a09736)
(cherry picked from commit a64426907d)
(cherry picked from commit 4b19215691)
(cherry picked from commit e635674435)
(cherry picked from commit 9cf501f1af)
(cherry picked from commit 0d6b934eba)
(cherry picked from commit 4b6c273879)
(cherry picked from commit 89b1315338)
(cherry picked from commit edd8e66ce9)

[GITEA] Add slow SQL query warning (squash) document the setting

(cherry picked from commit ce38599c51)
(cherry picked from commit 794aa67c68)
(cherry picked from commit a4c2c6b004)
(cherry picked from commit 97912752bc)
(cherry picked from commit 00b5327c97)
(cherry picked from commit 1069c860e7)
(cherry picked from commit 84241f42c8)
(cherry picked from commit e4bda0e845)
(cherry picked from commit 7357fb91bf)
(cherry picked from commit a8dd7f6da2)
(cherry picked from commit e636e9f4be)
(cherry picked from commit bf04ae8603)
(cherry picked from commit 93b19e3568)
(cherry picked from commit 83f91363ad)
(cherry picked from commit e34a05bc73)
This commit is contained in:
Gusted 2023-08-18 04:39:23 +02:00 committed by Earl Warren
parent 6e3c0be555
commit 68569aeee9
No known key found for this signature in database
GPG key ID: 0579CB2928A78A00
5 changed files with 73 additions and 0 deletions

View file

@ -412,6 +412,10 @@ USER = root
;; ;;
;; Whether execute database models migrations automatically ;; Whether execute database models migrations automatically
;AUTO_MIGRATION = true ;AUTO_MIGRATION = true
;;
;; Threshold value (in seconds) beyond which query execution time is logged as a warning in the xorm logger
;;
;SLOW_QUERY_TRESHOLD = 5s
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;
;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;

View file

@ -458,6 +458,7 @@ The following configuration set `Content-Type: application/vnd.android.package-a
- `MAX_IDLE_CONNS` **2**: Max idle database connections on connection pool, default is 2 - this will be capped to `MAX_OPEN_CONNS`. - `MAX_IDLE_CONNS` **2**: Max idle database connections on connection pool, default is 2 - this will be capped to `MAX_OPEN_CONNS`.
- `CONN_MAX_LIFETIME` **0 or 3s**: Sets the maximum amount of time a DB connection may be reused - default is 0, meaning there is no limit (except on MySQL where it is 3s - see #6804 & #7071). - `CONN_MAX_LIFETIME` **0 or 3s**: Sets the maximum amount of time a DB connection may be reused - default is 0, meaning there is no limit (except on MySQL where it is 3s - see #6804 & #7071).
- `AUTO_MIGRATION` **true**: Whether execute database models migrations automatically. - `AUTO_MIGRATION` **true**: Whether execute database models migrations automatically.
- `SLOW_QUERY_TRESHOLD` **5s**: Threshold value in seconds beyond which query execution time is logged as a warning in the xorm logger.
[^1]: It may be necessary to specify a hostport even when listening on a unix socket, as the port is part of the socket name. see [#24552](https://github.com/go-gitea/gitea/issues/24552#issuecomment-1681649367) for additional details. [^1]: It may be necessary to specify a hostport even when listening on a unix socket, as the port is part of the socket name. see [#24552](https://github.com/go-gitea/gitea/issues/24552#issuecomment-1681649367) for additional details.

View file

@ -11,10 +11,13 @@ import (
"io" "io"
"reflect" "reflect"
"strings" "strings"
"time"
"code.gitea.io/gitea/modules/log"
"code.gitea.io/gitea/modules/setting" "code.gitea.io/gitea/modules/setting"
"xorm.io/xorm" "xorm.io/xorm"
"xorm.io/xorm/contexts"
"xorm.io/xorm/names" "xorm.io/xorm/names"
"xorm.io/xorm/schemas" "xorm.io/xorm/schemas"
@ -144,6 +147,13 @@ func InitEngine(ctx context.Context) error {
xormEngine.SetConnMaxLifetime(setting.Database.ConnMaxLifetime) xormEngine.SetConnMaxLifetime(setting.Database.ConnMaxLifetime)
xormEngine.SetDefaultContext(ctx) xormEngine.SetDefaultContext(ctx)
if setting.Database.SlowQueryTreshold > 0 {
xormEngine.AddHook(&SlowQueryHook{
Treshold: setting.Database.SlowQueryTreshold,
Logger: log.GetLogger("xorm"),
})
}
SetDefaultEngine(ctx, xormEngine) SetDefaultEngine(ctx, xormEngine)
return nil return nil
} }
@ -299,3 +309,21 @@ func SetLogSQL(ctx context.Context, on bool) {
sess.Engine().ShowSQL(on) sess.Engine().ShowSQL(on)
} }
} }
type SlowQueryHook struct {
Treshold time.Duration
Logger log.Logger
}
var _ contexts.Hook = &SlowQueryHook{}
func (SlowQueryHook) BeforeProcess(c *contexts.ContextHook) (context.Context, error) {
return c.Ctx, nil
}
func (h *SlowQueryHook) AfterProcess(c *contexts.ContextHook) error {
if c.ExecuteTime >= h.Treshold {
h.Logger.Log(8, log.WARN, "[Slow SQL Query] %s %v - %v", c.SQL, c.Args, c.ExecuteTime)
}
return nil
}

View file

@ -6,15 +6,19 @@ package db_test
import ( import (
"path/filepath" "path/filepath"
"testing" "testing"
"time"
"code.gitea.io/gitea/models/db" "code.gitea.io/gitea/models/db"
issues_model "code.gitea.io/gitea/models/issues" issues_model "code.gitea.io/gitea/models/issues"
"code.gitea.io/gitea/models/unittest" "code.gitea.io/gitea/models/unittest"
"code.gitea.io/gitea/modules/log"
"code.gitea.io/gitea/modules/setting" "code.gitea.io/gitea/modules/setting"
"code.gitea.io/gitea/modules/test"
_ "code.gitea.io/gitea/cmd" // for TestPrimaryKeys _ "code.gitea.io/gitea/cmd" // for TestPrimaryKeys
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
"xorm.io/xorm"
) )
func TestDumpDatabase(t *testing.T) { func TestDumpDatabase(t *testing.T) {
@ -85,3 +89,37 @@ func TestPrimaryKeys(t *testing.T) {
} }
} }
} }
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)
}

View file

@ -45,6 +45,7 @@ var (
ConnMaxLifetime time.Duration ConnMaxLifetime time.Duration
IterateBufferSize int IterateBufferSize int
AutoMigration bool AutoMigration bool
SlowQueryTreshold time.Duration
}{ }{
Timeout: 500, Timeout: 500,
IterateBufferSize: 50, IterateBufferSize: 50,
@ -87,6 +88,7 @@ func loadDBSetting(rootCfg ConfigProvider) {
Database.DBConnectRetries = sec.Key("DB_RETRIES").MustInt(10) Database.DBConnectRetries = sec.Key("DB_RETRIES").MustInt(10)
Database.DBConnectBackoff = sec.Key("DB_RETRY_BACKOFF").MustDuration(3 * time.Second) Database.DBConnectBackoff = sec.Key("DB_RETRY_BACKOFF").MustDuration(3 * time.Second)
Database.AutoMigration = sec.Key("AUTO_MIGRATION").MustBool(true) Database.AutoMigration = sec.Key("AUTO_MIGRATION").MustBool(true)
Database.SlowQueryTreshold = sec.Key("SLOW_QUERY_TRESHOLD").MustDuration(5 * time.Second)
} }
// DBConnStr returns database connection string // DBConnStr returns database connection string