From 0a185c6d94cbeb3306218b67159cda59b756fe66 Mon Sep 17 00:00:00 2001
From: JamesMurkin <jamesmurkin@hotmail.com>
Date: Fri, 16 Aug 2024 14:12:26 +0100
Subject: [PATCH] [Lookout] Improve query logging to include duration +
 slow_query field

This will make it easier to find the cause of slow queries:
 - We can now see how long a given query is taking
 - We can filter the logs to those to show only slow queries using the new field

Signed-off-by: JamesMurkin <jamesmurkin@hotmail.com>
---
 internal/lookoutv2/repository/getjobs.go   | 4 +++-
 internal/lookoutv2/repository/groupjobs.go | 5 ++++-
 internal/lookoutv2/repository/util.go      | 4 +++-
 3 files changed, 10 insertions(+), 3 deletions(-)

diff --git a/internal/lookoutv2/repository/getjobs.go b/internal/lookoutv2/repository/getjobs.go
index fec4ee94aba..f59718d6d2f 100644
--- a/internal/lookoutv2/repository/getjobs.go
+++ b/internal/lookoutv2/repository/getjobs.go
@@ -66,13 +66,15 @@ func (r *SqlGetJobsRepository) getJobs(ctx *armadacontext.Context, filters []*mo
 	if err != nil {
 		return nil, err
 	}
-	logQuery(query, "GetJobs")
 	var jobs []*model.Job
 
+	queryStart := time.Now()
 	rows, err := r.db.Query(ctx, query.Sql, query.Args...)
 	if err != nil {
 		return nil, err
 	}
+	queryDuration := time.Now().Sub(queryStart)
+	logQuery(query, "GetJobs", queryDuration)
 	defer rows.Close()
 	for rows.Next() {
 		var row jobRow
diff --git a/internal/lookoutv2/repository/groupjobs.go b/internal/lookoutv2/repository/groupjobs.go
index 264b0c4bca4..8f42253d774 100644
--- a/internal/lookoutv2/repository/groupjobs.go
+++ b/internal/lookoutv2/repository/groupjobs.go
@@ -3,6 +3,7 @@ package repository
 import (
 	"fmt"
 	"strings"
+	"time"
 
 	"github.com/jackc/pgx/v5"
 	"github.com/jackc/pgx/v5/pgxpool"
@@ -57,14 +58,16 @@ func (r *SqlGroupJobsRepository) GroupBy(
 	if err != nil {
 		return nil, err
 	}
-	logQuery(query, "GroupBy")
 
 	var groups []*model.JobGroup
 
+	queryStart := time.Now()
 	groupRows, err := r.db.Query(ctx, query.Sql, query.Args...)
 	if err != nil {
 		return nil, err
 	}
+	queryDuration := time.Now().Sub(queryStart)
+	logQuery(query, "GroupBy", queryDuration)
 	groups, err = rowsToGroups(groupRows, groupedField, aggregates, filters)
 	if err != nil {
 		return nil, err
diff --git a/internal/lookoutv2/repository/util.go b/internal/lookoutv2/repository/util.go
index ac13d738801..444f164d404 100644
--- a/internal/lookoutv2/repository/util.go
+++ b/internal/lookoutv2/repository/util.go
@@ -734,10 +734,12 @@ func prefixAnnotations(prefix string, annotations map[string]string) map[string]
 	return prefixed
 }
 
-func logQuery(query *Query, description string) {
+func logQuery(query *Query, description string, duration time.Duration) {
 	log.
 		WithField("query", removeNewlinesAndTabs(query.Sql)).
 		WithField("values", query.Args).
+		WithField("duration", duration).
+		WithField("slow_query", duration > time.Second*3).
 		Debug(description)
 }