feat(ledger): refine benchmarks (#1679)

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

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,

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()))

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()))

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

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

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) {