From 9353d2f5815165b1ba7428b51b42c96fd5e98f66 Mon Sep 17 00:00:00 2001 From: Ragot Geoffrey Date: Wed, 18 Sep 2024 09:51:22 +0200 Subject: [PATCH] feat(ledger): refine benchmarks (#1679) --- components/ledger/Earthfile | 19 ++- components/ledger/benchmarks/ledger_test.go | 154 ------------------ components/ledger/cmd/serve.go | 2 +- .../internal/api/v1/middlewares_metrics.go | 2 +- .../internal/api/v2/middlewares_metrics.go | 2 +- .../storage/driver/{cli.go => module.go} | 0 .../{ => integration}/environment_test.go | 0 .../test/{ => integration}/scenario_test.go | 0 .../test/{ => integration}/suite_test.go | 0 .../test/performance/performance_test.go | 116 +++++++++++++ libs/go-libs/testing/utils/testing_main.go | 4 +- libs/go-libs/time/time.go | 4 +- 12 files changed, 133 insertions(+), 170 deletions(-) delete mode 100644 components/ledger/benchmarks/ledger_test.go rename components/ledger/internal/storage/driver/{cli.go => module.go} (100%) rename components/ledger/test/{ => integration}/environment_test.go (100%) rename components/ledger/test/{ => integration}/scenario_test.go (100%) rename components/ledger/test/{ => integration}/suite_test.go (100%) create mode 100644 components/ledger/test/performance/performance_test.go diff --git a/components/ledger/Earthfile b/components/ledger/Earthfile index 68ed300451..180a4c5b11 100644 --- a/components/ledger/Earthfile +++ b/components/ledger/Earthfile @@ -50,6 +50,7 @@ tests: COPY (+sources/*) /src WORKDIR /src/components/ledger COPY --dir --pass-args (+generate/*) . + COPY --dir test . ARG includeIntegrationTests="true" ARG coverage="" @@ -103,12 +104,14 @@ deploy-staging: lint: FROM core+builder-image COPY (+sources/*) /src - COPY --pass-args +tidy/go.* . WORKDIR /src/components/ledger + COPY --pass-args +tidy/go.* . + COPY --dir test . DO --pass-args stack+GO_LINT --ADDITIONAL_ARGUMENTS="--build-tags it" SAVE ARTIFACT cmd AS LOCAL cmd SAVE ARTIFACT internal AS LOCAL internal SAVE ARTIFACT pkg AS LOCAL pkg + SAVE ARTIFACT test AS LOCAL test SAVE ARTIFACT main.go AS LOCAL main.go pre-commit: @@ -122,9 +125,10 @@ bench: FROM core+builder-image DO --pass-args core+GO_INSTALL --package=golang.org/x/perf/cmd/benchstat@latest COPY (+sources/*) /src - WORKDIR /src/components/ledger/internal/storage/ledgerstore - ARG numberOfTransactions=10000 - ARG ledgers=10 + WORKDIR /src/components/ledger + COPY --dir test . + WORKDIR /src/components/ledger/test/performance + ARG benchTime=1s ARG count=1 ARG GOPROXY @@ -140,11 +144,8 @@ bench: WITH DOCKER --pull postgres:15-alpine RUN --mount type=cache,id=gopkgcache,target=${GOPATH}/pkg/mod \ --mount type=cache,id=gobuild,target=/root/.cache/go-build \ - go test -timeout $testTimeout -bench=$bench -run ^$ $additionalArgs \ - -benchtime=$benchTime \ - -count=$count \ - -ledgers=$ledgers \ - -transactions=$numberOfTransactions | tee -a /results.txt + go test -timeout $testTimeout -bench=$bench -run ^$ -tags it $additionalArgs \ + -benchtime=$benchTime | tee -a /results.txt END RUN benchstat /results.txt SAVE ARTIFACT /results.txt diff --git a/components/ledger/benchmarks/ledger_test.go b/components/ledger/benchmarks/ledger_test.go deleted file mode 100644 index 754ac8740c..0000000000 --- a/components/ledger/benchmarks/ledger_test.go +++ /dev/null @@ -1,154 +0,0 @@ -//go:build it - -package benchmarks - -import ( - "bytes" - "encoding/json" - "fmt" - "math/big" - "net/http" - "net/http/httptest" - "net/url" - "os" - "runtime" - "sync" - "sync/atomic" - "testing" - "time" - - ledger "github.com/formancehq/ledger/internal" - "github.com/formancehq/ledger/internal/api/backend" - v2 "github.com/formancehq/ledger/internal/api/v2" - "github.com/formancehq/ledger/internal/engine" - "github.com/formancehq/ledger/internal/opentelemetry/metrics" - "github.com/formancehq/ledger/internal/storage/storagetesting" - "github.com/formancehq/stack/libs/go-libs/api" - "github.com/formancehq/stack/libs/go-libs/auth" - "github.com/formancehq/stack/libs/go-libs/logging" - "github.com/google/uuid" - "github.com/stretchr/testify/require" -) - -func BenchmarkParallelWrites(b *testing.B) { - - ctx := logging.TestingContext() - - driver := storagetesting.StorageDriver(b) - resolver := engine.NewResolver(driver, engine.WithLogger(logging.FromContext(ctx))) - b.Cleanup(func() { - require.NoError(b, resolver.CloseLedgers(ctx)) - }) - - ledgerName := uuid.NewString() - - backend := backend.NewDefaultBackend(driver, "latest", resolver) - router := v2.NewRouter(backend, nil, metrics.NewNoOpRegistry(), auth.NewNoAuth(), testing.Verbose()) - handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - ctx := logging.ContextWithLogger(r.Context(), logging.FromContext(ctx)) - router.ServeHTTP(w, r.WithContext(ctx)) - }) - - totalDuration := atomic.Int64{} - b.SetParallelism(1000) - runtime.GC() - b.ResetTimer() - startOfBench := time.Now() - counter := atomic.Int64{} - longestTxLock := sync.Mutex{} - longestTransactionID := big.NewInt(0) - longestTransactionDuration := time.Duration(0) - b.RunParallel(func(pb *testing.PB) { - buf := bytes.NewBufferString("") - for pb.Next() { - buf.Reset() - id := counter.Add(1) - - //script := controllers.Script{ - // Script: core.Script{ - // Plain: fmt.Sprintf(` - // vars { - // account $account - // } - // - // send [USD/2 100] ( - // source = @world:%d allowing unbounded overdraft - // destination = $account - // )`, counter.Load()%100), - // }, - // Vars: map[string]any{ - // "account": fmt.Sprintf("accounts:%d", counter.Add(1)), - // }, - //} - - script := ledger.ScriptV1{ - Script: ledger.Script{ - Plain: `vars { - account $account -} - -send [USD/2 100] ( - source = @world - destination = $account -)`, - }, - Vars: map[string]any{ - "account": fmt.Sprintf("accounts:%d", id), - }, - } - - // script := controllers.Script{ - // Script: core.Script{ - // Plain: `vars { - // account $account - // account $src - //} - // - //send [USD/2 100] ( - // source = $src allowing unbounded overdraft - // destination = $account - //)`, - // }, - // Vars: map[string]any{ - // "src": fmt.Sprintf("world:%d", id), - // "account": fmt.Sprintf("accounts:%d", id), - // }, - // } - - err := json.NewEncoder(buf).Encode(ledger.TransactionRequest{ - Script: script, - }) - require.NoError(b, err) - - //ctx, _ := context.WithDeadline(ctx, time.Now().Add(10*time.Second)) - - req := httptest.NewRequest("POST", "/"+ledgerName+"/transactions", buf) - req = req.WithContext(ctx) - req.URL.RawQuery = url.Values{ - "async": []string{os.Getenv("ASYNC")}, - }.Encode() - rsp := httptest.NewRecorder() - - now := time.Now() - handler.ServeHTTP(rsp, req) - latency := time.Since(now).Milliseconds() - totalDuration.Add(latency) - - require.Equal(b, http.StatusOK, rsp.Code) - tx, _ := api.DecodeSingleResponse[ledger.Transaction](b, rsp.Body) - - longestTxLock.Lock() - if time.Millisecond*time.Duration(latency) > longestTransactionDuration { - longestTransactionID = tx.ID - longestTransactionDuration = time.Duration(latency) * time.Millisecond - } - longestTxLock.Unlock() - } - }) - - b.StopTimer() - b.Logf("Longest transaction: %d (%s)", longestTransactionID, longestTransactionDuration.String()) - b.ReportMetric((float64(time.Duration(b.N))/float64(time.Since(startOfBench)))*float64(time.Second), "t/s") - b.ReportMetric(float64(totalDuration.Load()/int64(b.N)), "ms/transaction") - runtime.GC() -} diff --git a/components/ledger/cmd/serve.go b/components/ledger/cmd/serve.go index 3addc2be88..32cb8705b6 100644 --- a/components/ledger/cmd/serve.go +++ b/components/ledger/cmd/serve.go @@ -80,7 +80,7 @@ func Log() func(h http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { start := time.Now() h.ServeHTTP(w, r) - latency := time.Since(start.Time) + latency := time.Since(start) logging.FromContext(r.Context()).WithFields(map[string]interface{}{ "method": r.Method, "path": r.URL.Path, diff --git a/components/ledger/internal/api/v1/middlewares_metrics.go b/components/ledger/internal/api/v1/middlewares_metrics.go index 0e21ad0cd6..e512c88eb9 100644 --- a/components/ledger/internal/api/v1/middlewares_metrics.go +++ b/components/ledger/internal/api/v1/middlewares_metrics.go @@ -40,7 +40,7 @@ func MetricsMiddleware(globalMetricsRegistry metrics.GlobalRegistry) func(h http start := time.Now() h.ServeHTTP(recorder, r) - latency := time.Since(start.Time) + latency := time.Since(start) attrs = append(attrs, attribute.String("route", chi.RouteContext(r.Context()).RoutePattern())) diff --git a/components/ledger/internal/api/v2/middlewares_metrics.go b/components/ledger/internal/api/v2/middlewares_metrics.go index 2fbc078acb..c961dd3076 100644 --- a/components/ledger/internal/api/v2/middlewares_metrics.go +++ b/components/ledger/internal/api/v2/middlewares_metrics.go @@ -40,7 +40,7 @@ func MetricsMiddleware(globalMetricsRegistry metrics.GlobalRegistry) func(h http start := time.Now() h.ServeHTTP(recorder, r) - latency := time.Since(start.Time) + latency := time.Since(start) attrs = append(attrs, attribute.String("route", chi.RouteContext(r.Context()).RoutePattern())) diff --git a/components/ledger/internal/storage/driver/cli.go b/components/ledger/internal/storage/driver/module.go similarity index 100% rename from components/ledger/internal/storage/driver/cli.go rename to components/ledger/internal/storage/driver/module.go diff --git a/components/ledger/test/environment_test.go b/components/ledger/test/integration/environment_test.go similarity index 100% rename from components/ledger/test/environment_test.go rename to components/ledger/test/integration/environment_test.go diff --git a/components/ledger/test/scenario_test.go b/components/ledger/test/integration/scenario_test.go similarity index 100% rename from components/ledger/test/scenario_test.go rename to components/ledger/test/integration/scenario_test.go diff --git a/components/ledger/test/suite_test.go b/components/ledger/test/integration/suite_test.go similarity index 100% rename from components/ledger/test/suite_test.go rename to components/ledger/test/integration/suite_test.go diff --git a/components/ledger/test/performance/performance_test.go b/components/ledger/test/performance/performance_test.go new file mode 100644 index 0000000000..61c688aa05 --- /dev/null +++ b/components/ledger/test/performance/performance_test.go @@ -0,0 +1,116 @@ +//go:build it + +package benchmarks + +import ( + "bytes" + "fmt" + "github.com/formancehq/ledger/pkg/testserver" + "github.com/formancehq/stack/ledger/client/models/components" + "github.com/formancehq/stack/libs/go-libs/logging" + "github.com/formancehq/stack/libs/go-libs/pointer" + "github.com/formancehq/stack/libs/go-libs/testing/docker" + "github.com/formancehq/stack/libs/go-libs/testing/platform/pgtesting" + "github.com/formancehq/stack/libs/go-libs/testing/utils" + "github.com/formancehq/stack/libs/go-libs/time" + "github.com/google/uuid" + "github.com/stretchr/testify/require" + "math/big" + "runtime" + "sync" + "sync/atomic" + "testing" +) + +var ( + dockerPool *docker.Pool + srv *pgtesting.PostgresServer +) + +func TestMain(m *testing.M) { + utils.WithTestMain(func(t *utils.TestingTForMain) int { + dockerPool = docker.NewPool(t, logging.Testing()) + srv = pgtesting.CreatePostgresServer(t, dockerPool) + + return m.Run() + }) +} + +func BenchmarkWorstCase(b *testing.B) { + + db := srv.NewDatabase(b) + + ctx := logging.TestingContext() + + ledgerName := uuid.NewString() + testServer := testserver.New(b, testserver.Configuration{ + PostgresConfiguration: db.ConnectionOptions(), + Debug: testing.Verbose(), + }) + testServer.Start() + defer testServer.Stop() + + _, err := testServer.Client().Ledger.V2.CreateLedger(ctx, ledgerName, &components.V2CreateLedgerRequest{}) + require.NoError(b, err) + + totalDuration := atomic.Int64{} + b.SetParallelism(1000) + runtime.GC() + b.ResetTimer() + startOfBench := time.Now() + counter := atomic.Int64{} + longestTxLock := sync.Mutex{} + longestTransactionID := big.NewInt(0) + longestTransactionDuration := time.Duration(0) + b.RunParallel(func(pb *testing.PB) { + buf := bytes.NewBufferString("") + for pb.Next() { + buf.Reset() + id := counter.Add(1) + now := time.Now() + + // todo: check why the generated sdk does not have the same signature as the global sdk + transactionResponse, err := testServer.Client().Ledger.V2.CreateTransaction(ctx, ledgerName, components.V2PostTransaction{ + Timestamp: nil, + Postings: nil, + Script: &components.Script{ + Plain: `vars { + account $account +} + +send [USD/2 100] ( + source = @world + destination = $account +)`, + Vars: map[string]any{ + "account": fmt.Sprintf("accounts:%d", id), + }, + }, + + Reference: nil, + Metadata: nil, + }, pointer.For(false), nil) + if err != nil { + return + } + require.NoError(b, err) + + latency := time.Since(now).Milliseconds() + totalDuration.Add(latency) + + longestTxLock.Lock() + if time.Millisecond*time.Duration(latency) > longestTransactionDuration { + longestTransactionID = transactionResponse.V2CreateTransactionResponse.Data.ID + longestTransactionDuration = time.Duration(latency) * time.Millisecond + } + longestTxLock.Unlock() + } + }) + + b.StopTimer() + b.Logf("Longest transaction: %d (%s)", longestTransactionID, longestTransactionDuration.String()) + b.ReportMetric((float64(time.Duration(b.N))/float64(time.Since(startOfBench)))*float64(time.Second), "t/s") + b.ReportMetric(float64(totalDuration.Load()/int64(b.N)), "ms/transaction") + + runtime.GC() +} diff --git a/libs/go-libs/testing/utils/testing_main.go b/libs/go-libs/testing/utils/testing_main.go index d311a38856..af7e00aa42 100644 --- a/libs/go-libs/testing/utils/testing_main.go +++ b/libs/go-libs/testing/utils/testing_main.go @@ -36,7 +36,7 @@ func (t *TestingTForMain) callCleanup() { } } -func (t *TestingTForMain) Close() { +func (t *TestingTForMain) close() { t.callCleanup() } @@ -45,7 +45,7 @@ func WithTestMain(fn func(main *TestingTForMain) int) { t := &TestingTForMain{} code := fn(t) - t.Close() + t.close() os.Exit(code) } diff --git a/libs/go-libs/time/time.go b/libs/go-libs/time/time.go index 5e077d01d9..fdbc6fbe94 100644 --- a/libs/go-libs/time/time.go +++ b/libs/go-libs/time/time.go @@ -128,8 +128,8 @@ func ParseTime(v string) (Time, error) { type Duration = time.Duration -func Since(t time.Time) Duration { - return time.Since(t) +func Since(t Time) Duration { + return time.Since(t.Time) } func ParseDuration(v string) (time.Duration, error) {