From 8c05a3c0733ea4ca5eb3247326ef7cea9e430c5e Mon Sep 17 00:00:00 2001
From: r-vdp <ramses@well-founded.dev>
Date: Thu, 18 Dec 2025 15:48:24 +0200
Subject: [PATCH] Log query execution times in the sqlstore

---
 api/api.go           |  7 -------
 sqlstore/sqlstore.go | 29 ++++++++++++++++++++---------
 2 files changed, 20 insertions(+), 16 deletions(-)

diff --git a/api/api.go b/api/api.go
index 01f0db6..bd39e1f 100644
--- a/api/api.go
+++ b/api/api.go
@@ -6,7 +6,6 @@ import (
 	"log/slog"
 	"os"
 	"runtime/debug"
-	"time"
 
 	"github.com/Arkiv-Network/query-api/query"
 	"github.com/Arkiv-Network/query-api/sqlstore"
@@ -49,12 +48,6 @@ func (api *arkivAPI) Query(
 	}()
 
 	// TODO log query plan
-	startTime := time.Now()
-	defer func() {
-		elapsed := time.Since(startTime)
-		queryDuration.Observe(elapsed.Seconds())
-		api.log.Info("query execution time", "seconds", elapsed.Seconds(), "query", req)
-	}()
 
 	response, err := api.store.QueryEntities(ctx, req, op, "postgresql")
 
diff --git a/sqlstore/sqlstore.go b/sqlstore/sqlstore.go
index 8806c54..2781f28 100644
--- a/sqlstore/sqlstore.go
+++ b/sqlstore/sqlstore.go
@@ -139,8 +139,8 @@ func (s *SQLStore) QueryEntities(
 
 	err = s.QueryEntitiesInternalIterator(
 		ctx,
-		evaluatedQuery.Query,
-		evaluatedQuery.Args,
+		req,
+		evaluatedQuery,
 		queryOptions,
 		func(entity *query.EntityData, cursor *query.Cursor) error {
 
@@ -180,16 +180,27 @@ func (s *SQLStore) QueryEntities(
 
 func (s *SQLStore) QueryEntitiesInternalIterator(
 	ctx context.Context,
-	queryStr string,
-	args []any,
+	originalQuery string,
+	evaluatedQuery *query.SelectQuery,
 	options *query.QueryOptions,
 	iterator func(*query.EntityData, *query.Cursor) error,
 ) error {
-	s.log.Info("Executing query", "query", queryStr, "sqlQuery", queryStr, "args", args)
+	s.log.Info(
+		"Executing query",
+		"query", originalQuery,
+		"sqlQuery", evaluatedQuery.Query,
+		"args", evaluatedQuery.Args,
+	)
+
+	startTime := time.Now()
+	defer func() {
+		elapsed := time.Since(startTime)
+		s.log.Info("query execution time", "seconds", elapsed.Seconds(), "query", originalQuery)
+	}()
 
-	rows, err := s.db.QueryContext(ctx, queryStr, args...)
+	rows, err := s.db.QueryContext(ctx, evaluatedQuery.Query, evaluatedQuery.Args...)
 	if err != nil {
-		return fmt.Errorf("failed to get entities for query: %s: %w", queryStr, err)
+		return fmt.Errorf("failed to get entities for query: %s: %w", originalQuery, err)
 	}
 	defer rows.Close()
 
@@ -197,7 +208,7 @@ func (s *SQLStore) QueryEntitiesInternalIterator(
 
 		err := rows.Err()
 		if err != nil {
-			return fmt.Errorf("failed to get entities for query: %s: %w", queryStr, err)
+			return fmt.Errorf("failed to get entities for query: %s: %w", originalQuery, err)
 		}
 
 		var (
@@ -254,7 +265,7 @@ func (s *SQLStore) QueryEntitiesInternalIterator(
 		}
 
 		if err := rows.Scan(dest...); err != nil {
-			return fmt.Errorf("failed to get entities for query: %s: %w", queryStr, err)
+			return fmt.Errorf("failed to get entities for query: %s: %w", originalQuery, err)
 		}
 
 		var keyHash *common.Hash