diff --git a/custom/conf/app.example.ini b/custom/conf/app.example.ini index 551ca83ca..e95947a4e 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_TRESHOLD = 5s ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; ;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;; diff --git a/docs/content/administration/config-cheat-sheet.en-us.md b/docs/content/administration/config-cheat-sheet.en-us.md index 33732d080..b0f0acf7e 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_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. diff --git a/models/db/engine.go b/models/db/engine.go index b2fbdcfbf..ad8ce7ecf 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" @@ -144,6 +147,13 @@ func InitEngine(ctx context.Context) error { xormEngine.SetConnMaxLifetime(setting.Database.ConnMaxLifetime) xormEngine.SetDefaultContext(ctx) + if setting.Database.SlowQueryTreshold > 0 { + xormEngine.AddHook(&SlowQueryHook{ + Treshold: setting.Database.SlowQueryTreshold, + Logger: log.GetLogger("xorm"), + }) + } + SetDefaultEngine(ctx, xormEngine) return nil } @@ -299,3 +309,21 @@ func SetLogSQL(ctx context.Context, on bool) { 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 +} diff --git a/models/db/engine_test.go b/models/db/engine_test.go index c9ae5f154..ba922821b 100644 --- a/models/db/engine_test.go +++ b/models/db/engine_test.go @@ -6,15 +6,19 @@ package db_test import ( "path/filepath" "testing" + "time" "code.gitea.io/gitea/models/db" issues_model "code.gitea.io/gitea/models/issues" "code.gitea.io/gitea/models/unittest" + "code.gitea.io/gitea/modules/log" "code.gitea.io/gitea/modules/setting" + "code.gitea.io/gitea/modules/test" _ "code.gitea.io/gitea/cmd" // for TestPrimaryKeys "github.com/stretchr/testify/assert" + "xorm.io/xorm" ) 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) +} diff --git a/modules/setting/database.go b/modules/setting/database.go index e200b15b2..54551b44b 100644 --- a/modules/setting/database.go +++ b/modules/setting/database.go @@ -45,6 +45,7 @@ var ( ConnMaxLifetime time.Duration IterateBufferSize int AutoMigration bool + SlowQueryTreshold 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.SlowQueryTreshold = sec.Key("SLOW_QUERY_TRESHOLD").MustDuration(5 * time.Second) } // DBConnStr returns database connection string