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 <postmaster@gusted.xyz>
Co-authored-by: Giteabot <teabot@gitea.io>
Co-authored-by: 6543 <6543@obermui.de>

1 files changed, 31 insertions, 0 deletions

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
+}