From 08d352a0ade5ab4d4ed6be58ad0a76982974d56d Mon Sep 17 00:00:00 2001 From: Marcus Efraimsson Date: Wed, 21 Sep 2022 21:17:26 +0200 Subject: [PATCH] Instrumentation: Improve instrumentation of server lock service (#55516) Improve log and trace instrumentation of the server lock service. Closes #55455 --- pkg/infra/serverlock/serverlock.go | 71 +++++++++++++++++++++---- pkg/infra/serverlock/serverlock_test.go | 2 + 2 files changed, 64 insertions(+), 9 deletions(-) diff --git a/pkg/infra/serverlock/serverlock.go b/pkg/infra/serverlock/serverlock.go index f02b462bfa3..1e2d7cfd024 100644 --- a/pkg/infra/serverlock/serverlock.go +++ b/pkg/infra/serverlock/serverlock.go @@ -6,12 +6,15 @@ import ( "time" "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/infra/tracing" "github.com/grafana/grafana/pkg/services/sqlstore" + "go.opentelemetry.io/otel/attribute" ) -func ProvideService(sqlStore *sqlstore.SQLStore) *ServerLockService { +func ProvideService(sqlStore *sqlstore.SQLStore, tracer tracing.Tracer) *ServerLockService { return &ServerLockService{ SQLStore: sqlStore, + tracer: tracer, log: log.New("infra.lockservice"), } } @@ -21,6 +24,7 @@ func ProvideService(sqlStore *sqlstore.SQLStore) *ServerLockService { // them up (ie, use the same actionName for both of them). type ServerLockService struct { SQLStore *sqlstore.SQLStore + tracer tracing.Tracer log log.Logger } @@ -28,9 +32,18 @@ type ServerLockService struct { // `fn` function when successful. This should not be used at low internal. But services // that needs to be run once every ex 10m. func (sl *ServerLockService) LockAndExecute(ctx context.Context, actionName string, maxInterval time.Duration, fn func(ctx context.Context)) error { + start := time.Now() + ctx, span := sl.tracer.Start(ctx, "ServerLockService.LockAndExecute") + span.SetAttributes("serverlock.actionName", actionName, attribute.Key("serverlock.actionName").String(actionName)) + defer span.End() + + ctxLogger := sl.log.FromContext(ctx) + ctxLogger.Debug("Start LockAndExecute", "actionName", actionName) + // gets or creates a lockable row rowLock, err := sl.getOrCreate(ctx, actionName) if err != nil { + span.RecordError(err) return err } @@ -39,20 +52,25 @@ func (sl *ServerLockService) LockAndExecute(ctx context.Context, actionName stri return nil } - // try to get lock based on rowLow version + // try to get lock based on rowLock version acquiredLock, err := sl.acquireLock(ctx, rowLock) if err != nil { + span.RecordError(err) return err } if acquiredLock { - fn(ctx) + sl.executeFunc(ctx, actionName, fn) } + ctxLogger.Debug("LockAndExecute finished", "actionName", actionName, "acquiredLock", acquiredLock, "duration", time.Since(start)) + return nil } func (sl *ServerLockService) acquireLock(ctx context.Context, serverLock *serverLock) (bool, error) { + ctx, span := sl.tracer.Start(ctx, "ServerLockService.acquireLock") + defer span.End() var result bool err := sl.SQLStore.WithDbSession(ctx, func(dbSession *sqlstore.DBSession) error { @@ -78,6 +96,9 @@ func (sl *ServerLockService) acquireLock(ctx context.Context, serverLock *server } func (sl *ServerLockService) getOrCreate(ctx context.Context, actionName string) (*serverLock, error) { + ctx, span := sl.tracer.Start(ctx, "ServerLockService.getOrCreate") + defer span.End() + var result *serverLock err := sl.SQLStore.WithTransactionalDbSession(ctx, func(dbSession *sqlstore.DBSession) error { @@ -115,26 +136,40 @@ func (sl *ServerLockService) getOrCreate(ctx context.Context, actionName string) // database is older than maxInterval, we will assume the lock as timeouted. The 'maxInterval' parameter should be so long // that is impossible for 2 processes to run at the same time. func (sl *ServerLockService) LockExecuteAndRelease(ctx context.Context, actionName string, maxInterval time.Duration, fn func(ctx context.Context)) error { + start := time.Now() + ctx, span := sl.tracer.Start(ctx, "ServerLockService.LockExecuteAndRelease") + span.SetAttributes("serverlock.actionName", actionName, attribute.Key("serverlock.actionName").String(actionName)) + defer span.End() + + ctxLogger := sl.log.FromContext(ctx) + ctxLogger.Debug("Start LockExecuteAndRelease", "actionName", actionName) + err := sl.acquireForRelease(ctx, actionName, maxInterval) // could not get the lock, returning if err != nil { + span.RecordError(err) return err } - // execute! - fn(ctx) + sl.executeFunc(ctx, actionName, fn) err = sl.releaseLock(ctx, actionName) if err != nil { - sl.log.Error("Error releasing the lock.", err) + span.RecordError(err) + ctxLogger.Error("Failed to release the lock", "error", err) } + ctxLogger.Debug("LockExecuteAndRelease finished", "actionName", actionName, "duration", time.Since(start)) + return nil } // acquireForRelease will check if the lock is already on the database, if it is, will check with maxInterval if it is // timeouted. Returns nil error if the lock was acquired correctly func (sl *ServerLockService) acquireForRelease(ctx context.Context, actionName string, maxInterval time.Duration) error { + ctx, span := sl.tracer.Start(ctx, "ServerLockService.acquireForRelease") + defer span.End() + // getting the lock - as the action name has a Unique constraint, this will fail if the lock is already on the database err := sl.SQLStore.WithTransactionalDbSession(ctx, func(dbSession *sqlstore.DBSession) error { // we need to find if the lock is in the database @@ -144,6 +179,8 @@ func (sl *ServerLockService) acquireForRelease(ctx context.Context, actionName s return err } + ctxLogger := sl.log.FromContext(ctx) + if len(lockRows) > 0 { result := lockRows[0] if sl.isLockWithinInterval(result, maxInterval) { @@ -157,7 +194,7 @@ func (sl *ServerLockService) acquireForRelease(ctx context.Context, actionName s return err } if affected != 1 { - sl.log.Error("Expected rows affected to be 1 if there was no error.", "actionName", actionName, "rowAffected", affected) + ctxLogger.Error("Expected rows affected to be 1 if there was no error", "actionName", actionName, "rowsAffected", affected) } return nil } @@ -175,7 +212,7 @@ func (sl *ServerLockService) acquireForRelease(ctx context.Context, actionName s if affected != 1 { // this means that there was no error but there is something not working correctly - sl.log.Error("Expected rows affected to be 1 if there was no error.", "actionName", actionName, "rowAffected", affected) + ctxLogger.Error("Expected rows affected to be 1 if there was no error", "actionName", actionName, "rowsAffected", affected) } } return nil @@ -186,6 +223,9 @@ func (sl *ServerLockService) acquireForRelease(ctx context.Context, actionName s // releaseLock will delete the row at the database. This is only intended to be used within the scope of LockExecuteAndRelease // method, but not as to manually release a Lock func (sl *ServerLockService) releaseLock(ctx context.Context, actionName string) error { + ctx, span := sl.tracer.Start(ctx, "ServerLockService.releaseLock") + defer span.End() + err := sl.SQLStore.WithDbSession(ctx, func(dbSession *sqlstore.DBSession) error { sql := `DELETE FROM server_lock WHERE operation_uid=? ` @@ -195,7 +235,7 @@ func (sl *ServerLockService) releaseLock(ctx context.Context, actionName string) } affected, err := res.RowsAffected() if affected != 1 { - sl.log.Debug("Error releasing lock ", "actionName", actionName, "affected", affected) + sl.log.FromContext(ctx).Debug("Error releasing lock", "actionName", actionName, "rowsAffected", affected) } return err }) @@ -212,3 +252,16 @@ func (sl *ServerLockService) isLockWithinInterval(lock *serverLock, maxInterval } return false } + +func (sl ServerLockService) executeFunc(ctx context.Context, actionName string, fn func(ctx context.Context)) { + start := time.Now() + ctx, span := sl.tracer.Start(ctx, "ServerLockService.executeFunc") + defer span.End() + + ctxLogger := sl.log.FromContext(ctx) + ctxLogger.Debug("Start execution", "actionName", actionName) + + fn(ctx) + + ctxLogger.Debug("Execution finished", "actionName", actionName, "duration", time.Since(start)) +} diff --git a/pkg/infra/serverlock/serverlock_test.go b/pkg/infra/serverlock/serverlock_test.go index d042b59e4c6..55554245953 100644 --- a/pkg/infra/serverlock/serverlock_test.go +++ b/pkg/infra/serverlock/serverlock_test.go @@ -9,6 +9,7 @@ import ( "github.com/stretchr/testify/require" "github.com/grafana/grafana/pkg/infra/log" + "github.com/grafana/grafana/pkg/infra/tracing" "github.com/grafana/grafana/pkg/services/sqlstore" ) @@ -19,6 +20,7 @@ func createTestableServerLock(t *testing.T) *ServerLockService { return &ServerLockService{ SQLStore: store, + tracer: tracing.InitializeTracerForTest(), log: log.New("test-logger"), } }