From b748d62b461f9f23823f8772bc708b44b15a23a7 Mon Sep 17 00:00:00 2001 From: Earl Warren <109468362+earl-warren@users.noreply.github.com> Date: Fri, 23 Feb 2024 01:57:24 +0100 Subject: [PATCH] Add slow SQL query warning (#27545) - Databases are one of the most important parts of Forgejo, every interaction uses the database in one way or another. Therefore, it is important to maintain the database and recognize when the server is not doing well with the database. There already is 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 9cf501f1af4cd870221cef6af489618785b71186) --------- Co-authored-by: Gusted Co-authored-by: Giteabot Co-authored-by: 6543 <6543@obermui.de> --- custom/conf/app.example.ini | 4 ++ .../config-cheat-sheet.en-us.md | 1 + models/db/engine.go | 31 ++++++++++++++ modules/setting/database.go | 42 ++++++++++--------- 4 files changed, 58 insertions(+), 20 deletions(-) diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 4aae1c497f..a360970593 100644 --- a/custom/conf/app.example.ini +++ b/custom/conf/app.example.ini @@ -412,6 +412,10 @@ USER = root ;; ;; Whether execute database models migrations automatically ;AUTO_MIGRATION = true +;; +;; Threshold value (in seconds) beyond which query execution time is logged as a warning in the xorm logger +;; +;SLOW_QUERY_THRESHOLD = 5s ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; diff --git a/docs/content/administration/config-cheat-sheet.en-us.md b/docs/content/administration/config-cheat-sheet.en-us.md index 415176d4ff..838e26b0f6 100644 --- a/docs/content/administration/config-cheat-sheet.en-us.md +++ b/docs/content/administration/config-cheat-sheet.en-us.md @@ -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`. - `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. +- `SLOW_QUERY_THRESHOLD` **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. diff --git a/models/db/engine.go b/models/db/engine.go index 2cd1c36c58..2a2743e927 100755 --- a/models/db/engine.go +++ b/models/db/engine.go @@ -11,10 +11,13 @@ import ( "io" "reflect" "strings" + "time" + "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/setting" "xorm.io/xorm" + "xorm.io/xorm/contexts" "xorm.io/xorm/names" "xorm.io/xorm/schemas" @@ -143,6 +146,13 @@ func InitEngine(ctx context.Context) error { xormEngine.SetConnMaxLifetime(setting.Database.ConnMaxLifetime) xormEngine.SetDefaultContext(ctx) + if setting.Database.SlowQueryThreshold > 0 { + xormEngine.AddHook(&SlowQueryHook{ + Threshold: setting.Database.SlowQueryThreshold, + Logger: log.GetLogger("xorm"), + }) + } + SetDefaultEngine(ctx, xormEngine) return nil } @@ -298,3 +308,24 @@ func SetLogSQL(ctx context.Context, on bool) { sess.Engine().ShowSQL(on) } } + +type SlowQueryHook struct { + Threshold 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.Threshold { + // 8 is the amount of skips passed to runtime.Caller, so that in the log the correct function + // is being displayed (the function that ultimately wants to execute the query in the code) + // instead of the function of the slow query hook being called. + h.Logger.Log(8, log.WARN, "[Slow SQL Query] %s %v - %v", c.SQL, c.Args, c.ExecuteTime) + } + return nil +} diff --git a/modules/setting/database.go b/modules/setting/database.go index e200b15b2e..1a4bf64805 100644 --- a/modules/setting/database.go +++ b/modules/setting/database.go @@ -25,26 +25,27 @@ var ( // Database holds the database settings Database = struct { - Type DatabaseType - Host string - Name string - User string - Passwd string - Schema string - SSLMode string - Path string - LogSQL bool - MysqlCharset string - CharsetCollation string - Timeout int // seconds - SQLiteJournalMode string - DBConnectRetries int - DBConnectBackoff time.Duration - MaxIdleConns int - MaxOpenConns int - ConnMaxLifetime time.Duration - IterateBufferSize int - AutoMigration bool + Type DatabaseType + Host string + Name string + User string + Passwd string + Schema string + SSLMode string + Path string + LogSQL bool + MysqlCharset string + CharsetCollation string + Timeout int // seconds + SQLiteJournalMode string + DBConnectRetries int + DBConnectBackoff time.Duration + MaxIdleConns int + MaxOpenConns int + ConnMaxLifetime time.Duration + IterateBufferSize int + AutoMigration bool + SlowQueryThreshold time.Duration }{ Timeout: 500, IterateBufferSize: 50, @@ -87,6 +88,7 @@ func loadDBSetting(rootCfg ConfigProvider) { Database.DBConnectRetries = sec.Key("DB_RETRIES").MustInt(10) Database.DBConnectBackoff = sec.Key("DB_RETRY_BACKOFF").MustDuration(3 * time.Second) Database.AutoMigration = sec.Key("AUTO_MIGRATION").MustBool(true) + Database.SlowQueryThreshold = sec.Key("SLOW_QUERY_THRESHOLD").MustDuration(5 * time.Second) } // DBConnStr returns database connection string