From d0fd0c7bed42205c70b613b7de0838c4787e232b Mon Sep 17 00:00:00 2001 From: ccamel Date: Sat, 9 Nov 2024 15:09:02 +0100 Subject: [PATCH 1/3] feat(logic): introduce telemetry to track predicate call counts --- x/logic/keeper/interpreter.go | 28 +++++++++--------- x/logic/keeper/metrics.go | 55 +++++++++++++++++++++++++++++++++++ 2 files changed, 69 insertions(+), 14 deletions(-) create mode 100644 x/logic/keeper/metrics.go diff --git a/x/logic/keeper/interpreter.go b/x/logic/keeper/interpreter.go index e9421549..4737771c 100644 --- a/x/logic/keeper/interpreter.go +++ b/x/logic/keeper/interpreter.go @@ -105,6 +105,7 @@ func (k Keeper) newInterpreter(ctx context.Context, params types.Params) (*prolo interpreter.WithHooks( whitelistBlacklistHookFn(whitelistPredicates, blacklistPredicates), gasMeterHookFn(sdkctx, params.GetGasPolicy()), + telemetryPredicateCallCounterHookFn(), ), interpreter.WithPredicates(ctx, interpreter.RegistryNames), interpreter.WithBootstrap(ctx, util.NonZeroOrDefault(interpreterParams.GetBootstrap(), bootstrap.Bootstrap())), @@ -135,23 +136,24 @@ func whitelistBlacklistHookFn(whitelist, blacklist []string) engine.HookFunc { return nil } - predicateStringer, ok := operand.(fmt.Stringer) + predicate, ok := stringifyOperand(operand) if !ok { return engine.SyntaxError(operand, env) } - predicate := predicateStringer.String() + if !interpreter.IsRegistered(predicate) { + return nil + } - if interpreter.IsRegistered(predicate) { - if _, found := allowed.Get(predicate); !found { - return engine.PermissionError( - prolog2.AtomOperationExecute, - prolog2.AtomPermissionForbiddenPredicate, - engine.NewAtom(predicate), - env, - ) - } + if _, found := allowed.Get(predicate); !found { + return engine.PermissionError( + prolog2.AtomOperationExecute, + prolog2.AtomPermissionForbiddenPredicate, + engine.NewAtom(predicate), + env, + ) } + return nil } } @@ -166,13 +168,11 @@ func gasMeterHookFn(ctx context.Context, gasPolicy types.GasPolicy) engine.HookF return nil } - operandStringer, ok := operand.(fmt.Stringer) + predicate, ok := stringifyOperand(operand) if !ok { return engine.SyntaxError(operand, env) } - predicate := operandStringer.String() - cost := lookupCost(predicate, lo.CoalesceOrEmpty(gasPolicy.DefaultPredicateCost, defaultPredicateCost), gasPolicy.PredicateCosts) diff --git a/x/logic/keeper/metrics.go b/x/logic/keeper/metrics.go new file mode 100644 index 00000000..2f74fde8 --- /dev/null +++ b/x/logic/keeper/metrics.go @@ -0,0 +1,55 @@ +package keeper + +import ( + "fmt" + + "github.com/axone-protocol/prolog/engine" + "github.com/hashicorp/go-metrics" + + "github.com/cosmos/cosmos-sdk/telemetry" + + "github.com/axone-protocol/axoned/v10/x/logic/interpreter" + "github.com/axone-protocol/axoned/v10/x/logic/types" +) + +var metricsKeys = []string{types.ModuleName, "vm", "predicate"} + +const ( + labelPredicate = "predicate" +) + +func telemetryPredicateCallCounterHookFn() engine.HookFunc { + return func(opcode engine.Opcode, operand engine.Term, _ *engine.Env) error { + if opcode != engine.OpCall { + return nil + } + + predicate, ok := stringifyOperand(operand) + if !ok { + return nil + } + + if !interpreter.IsRegistered(predicate) { + return nil + } + + telemetry.IncrCounterWithLabels( + metricsKeys, + 1, + []metrics.Label{ + telemetry.NewLabel(labelPredicate, predicate), + }, + ) + + return nil + } +} + +// stringifyOperand returns the string representation of the operand if it implements fmt.Stringer. +// It returns an empty string and false if the operand does not have a string representation. +func stringifyOperand(operand engine.Term) (string, bool) { + if stringer, ok := operand.(fmt.Stringer); ok { + return stringer.String(), true + } + return "", false +} From f550a535dbb0327876c64b6d0e93eb579df70af2 Mon Sep 17 00:00:00 2001 From: ccamel Date: Sat, 9 Nov 2024 15:09:59 +0100 Subject: [PATCH 2/3] feat(logic): implement telemetry for predicate execution duration metrics --- x/logic/keeper/interpreter.go | 1 + x/logic/keeper/metrics.go | 25 +++++++++++++++++++++++++ 2 files changed, 26 insertions(+) diff --git a/x/logic/keeper/interpreter.go b/x/logic/keeper/interpreter.go index 4737771c..6894de5b 100644 --- a/x/logic/keeper/interpreter.go +++ b/x/logic/keeper/interpreter.go @@ -106,6 +106,7 @@ func (k Keeper) newInterpreter(ctx context.Context, params types.Params) (*prolo whitelistBlacklistHookFn(whitelistPredicates, blacklistPredicates), gasMeterHookFn(sdkctx, params.GetGasPolicy()), telemetryPredicateCallCounterHookFn(), + telemetryPredicateDurationHookFn(), ), interpreter.WithPredicates(ctx, interpreter.RegistryNames), interpreter.WithBootstrap(ctx, util.NonZeroOrDefault(interpreterParams.GetBootstrap(), bootstrap.Bootstrap())), diff --git a/x/logic/keeper/metrics.go b/x/logic/keeper/metrics.go index 2f74fde8..41e30b30 100644 --- a/x/logic/keeper/metrics.go +++ b/x/logic/keeper/metrics.go @@ -2,6 +2,7 @@ package keeper import ( "fmt" + "time" "github.com/axone-protocol/prolog/engine" "github.com/hashicorp/go-metrics" @@ -45,6 +46,30 @@ func telemetryPredicateCallCounterHookFn() engine.HookFunc { } } +func telemetryPredicateDurationHookFn() engine.HookFunc { + var predicate string + var start time.Time + return func(opcode engine.Opcode, operand engine.Term, _ *engine.Env) error { + if opcode != engine.OpCall { + if predicate != "" { + telemetry.MeasureSince(start, append(metricsKeys, predicate)...) + predicate = "" + start = time.Time{} + } + return nil + } + + var ok bool + if predicate, ok = stringifyOperand(operand); !ok { + return nil + } + + start = telemetry.Now() + + return nil + } +} + // stringifyOperand returns the string representation of the operand if it implements fmt.Stringer. // It returns an empty string and false if the operand does not have a string representation. func stringifyOperand(operand engine.Term) (string, bool) { From 216015c32c0003092c40a3594041c83a7b518401 Mon Sep 17 00:00:00 2001 From: ccamel Date: Sun, 10 Nov 2024 16:03:32 +0100 Subject: [PATCH 3/3] test(logic): put stringifyOperand under test --- x/logic/keeper/metrics_test.go | 51 ++++++++++++++++++++++++++++++++++ 1 file changed, 51 insertions(+) create mode 100644 x/logic/keeper/metrics_test.go diff --git a/x/logic/keeper/metrics_test.go b/x/logic/keeper/metrics_test.go new file mode 100644 index 00000000..e15eb398 --- /dev/null +++ b/x/logic/keeper/metrics_test.go @@ -0,0 +1,51 @@ +package keeper + +import ( + "fmt" + "testing" + + "github.com/axone-protocol/prolog/engine" + + . "github.com/smartystreets/goconvey/convey" +) + +func TestStringifyOperand(t *testing.T) { + Convey("Given various inputs to stringifyOperand", t, func() { + testCases := []struct { + description string + input engine.Term + expected string + ok bool + }{ + { + description: "an operand implementing fmt.Stringer", + input: engine.NewAtom("foo"), + expected: "foo", + ok: true, + }, + { + description: "an operand not implementing fmt.Stringer", + input: engine.NewAtom("foo").Apply(engine.NewAtom("bar")), + expected: "", + ok: false, + }, + { + description: "the nil operand", + input: nil, + expected: "", + ok: false, + }, + } + + for _, tc := range testCases { + Convey(fmt.Sprintf("When input is %s", tc.description), func() { + result, ok := stringifyOperand(tc.input) + + Convey("Then the result should match the expected output", func() { + So(result, ShouldEqual, tc.expected) + So(ok, ShouldEqual, tc.ok) + }) + }) + } + }) +}