diff --git a/models/db/engine.go b/models/db/engine.go index 182d8cd993696..9aec903780313 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" @@ -146,6 +149,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 e3dbfbdc24205..fbc40102dac43 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) { @@ -84,3 +88,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 709655368c67b..219c96e4d7190 100644 --- a/modules/setting/database.go +++ b/modules/setting/database.go @@ -44,6 +44,7 @@ var ( ConnMaxLifetime time.Duration IterateBufferSize int AutoMigration bool + SlowQueryTreshold time.Duration }{ Timeout: 500, IterateBufferSize: 50, @@ -86,6 +87,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