Slow Query Logging and Tracing in Go Services Explained

Every service has a few queries that are slow and nobody knows which. A slow query log answers that: it writes down each statement that took longer than a threshold, with enough context to find it in the code. There are two places to log from, the Go client and the PostgreSQL server, and they see different things. This article sets up both on Go 1.25.6 with pgx v5.11.0 and PostgreSQL 18.6, runs five statements through them, and compares what each recorded.

It is part of the database cornerstone. Once the log names a query, index basics and reading EXPLAIN is the next tool, and when a whole request is slow, tracing with OpenTelemetry shows where the time went.

Logging from the client

pgx calls a QueryTracer before and after each statement. The tracer below stores the start time and the SQL in the context returned from TraceQueryStart, and on TraceQueryEnd computes the duration and logs it through log/slog if it passed the threshold:

package main

import (
	"context"
	"log"
	"log/slog"
	"os"
	"strings"
	"time"

	"github.com/jackc/pgx/v5"
	"github.com/jackc/pgx/v5/pgxpool"
)

const dsn = "postgres://postgres:[email protected]:55432/lab?sslmode=disable&application_name=slow627"

const threshold = 40 * time.Millisecond

type startKey struct{}

type slowLog struct{ logger *slog.Logger }

func (s slowLog) TraceQueryStart(ctx context.Context, _ *pgx.Conn, d pgx.TraceQueryStartData) context.Context {
	// The statement and the number of arguments are kept; the argument values never are, because they can hold personal data.
	return context.WithValue(ctx, startKey{}, struct {
		at   time.Time
		sql  string
		args int
	}{time.Now(), d.SQL, len(d.Args)})
}

func (s slowLog) TraceQueryEnd(ctx context.Context, _ *pgx.Conn, d pgx.TraceQueryEndData) {
	st, ok := ctx.Value(startKey{}).(struct {
		at   time.Time
		sql  string
		args int
	})
	if !ok {
		return
	}
	took := time.Since(st.at)
	if took < threshold {
		return
	}
	sql := strings.Join(strings.Fields(st.sql), " ")
	if len(sql) > 60 {
		sql = sql[:60] + "..."
	}
	s.logger.Warn("slow query", "over_ms", took.Milliseconds()/10*10, "args", st.args, "rows", d.CommandTag.RowsAffected(), "err", d.Err, "sql", sql)
}

func main() {
	ctx := context.Background()
	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
		if a.Key == slog.TimeKey {
			return slog.Attr{}
		}
		return a
	}}))
	cfg, err := pgxpool.ParseConfig(dsn)
	if err != nil {
		log.Fatal(err)
	}
	cfg.ConnConfig.Tracer = slowLog{logger}
	pool, err := pgxpool.NewWithConfig(ctx, cfg)
	if err != nil {
		log.Fatal(err)
	}
	defer pool.Close()

	var n int
	_ = pool.QueryRow(ctx, "/* slow627 */ select 1").Scan(&n)                                                   // fast
	_ = pool.QueryRow(ctx, "/* slow627 */ select count(*) from generate_series(1, $1)", 100).Scan(&n)           // fast
	_ = pool.QueryRow(ctx, "/* slow627 */ select pg_sleep(0.08)::text::int is null from (select 1) s").Scan(&n) // slow, and an error
	_, _ = pool.Exec(ctx, "/* slow627 */ select pg_sleep(0.12)")                                                // slow
	logger.Info("done")
}

Some choices in it are worth copying.

Argument values are never logged. The tracer records the number of arguments, not their contents. Query arguments hold emails, tokens and other personal data, and a log file is read by more people and kept longer than the database. If you need to reproduce a slow query, log the SQL and run it with similar values by hand, or log the values only for non production environments.

The SQL is normalised and cut. Whitespace is collapsed to one line and the text is limited to 60 characters followed by ..., so a generated statement with a hundred columns does not fill a log line. A trace identifier or a comment at the front of the statement (the lab uses /* slow627 */) helps find it in the server log, as shown below.

The result is included. rows comes from the command tag and err from the end data. A slow statement that failed is a different problem from one that succeeded, and the error tells which.

The duration is rounded down to ten milliseconds in the lab (over_ms=80) only so the printed output is stable. In a real log keep the exact value.

Logging from the server

PostgreSQL has its own switch, log_min_duration_statement. Set to 40ms, every statement that finishes in 40 milliseconds or more is written to the server log with its duration. It can be set in postgresql.conf, per database or role with alter database ... set, or for the whole server at runtime:

docker exec gh-lab-pg psql -U postgres -c "alter system set log_min_duration_statement = '40ms'" -c "select pg_reload_conf()"

alter system writes the setting to a file and pg_reload_conf() applies it without a restart. The script in the lab turns it on, runs the Go program, reads the server log and turns it off again with alter system reset.

set -e
docker exec gh-lab-pg psql -U postgres -qc "alter system set log_min_duration_statement = '40ms'" -c "select pg_reload_conf()" >/dev/null
sleep 1
go run .
sleep 1
echo "--- PostgreSQL server log"
docker logs --since 20s gh-lab-pg 2>&1 | grep -E "duration: .*slow627|ERROR:  invalid input" | sed -E 's/^[0-9-]+ [0-9:.]+ UTC //' | cut -c1-120
docker exec gh-lab-pg psql -U postgres -qc "alter system reset log_min_duration_statement" -c "select pg_reload_conf()" >/dev/null

level=WARN msg="slow query" over_ms=80 args=0 rows=0 err="ERROR: invalid input syntax for type integer: \"\" (SQLSTATE 22P02)" sql="/* slow627 */ select pg_sleep(0.08)::text::int is null from ..."
level=WARN msg="slow query" over_ms=120 args=0 rows=1 err=<nil> sql="/* slow627 */ select pg_sleep(0.12)"
level=INFO msg=done
--- PostgreSQL server log
[3966] ERROR:  invalid input syntax for type integer: ""
[3966] LOG:  duration: 121.256 ms  statement: /* slow627 */ select pg_sleep(0.12)

What each log saw

The program ran five statements: two fast ones, and three that sleep. The output has two halves.

The client log reported two slow queries:

• over_ms=80 ... err="ERROR: invalid input syntax for type integer" for the statement that slept 80 milliseconds and then failed on a bad cast. It took long enough to be slow and it failed, and the log says both.
• over_ms=120 rows=1 err=<nil> for select pg_sleep(0.12).

The server log recorded one duration line: duration: 121.396 ms statement: /* slow627 */ select pg_sleep(0.12). The failing statement is there only as an ERROR: invalid input syntax for type integer: "" line, without a duration. PostgreSQL logs a duration for statements that complete, and a statement that errors is logged as an error under log_min_error_statement. A slow query that fails, such as a timeout or a deadlock, therefore needs the client log or the error log to be seen, and the duration log alone would miss it. That is a good reason to keep both.

The two durations also differ in what they measure. The server's 121.396ms is time inside PostgreSQL. The client's figure includes sending the statement, waiting for a free connection in the pool, and receiving the rows, so it is always the larger and is the one the user experienced. A gap between them is a finding: a large difference with a quick server time means the problem is in the network, the pool or the transfer of too many rows, not in the query plan.

What to log and what to do with it

• Pick a threshold from your latency target. 100ms to 500ms is a common start for a web service. Too low drowns the log, too high hides the death by a thousand cuts. Lower it temporarily when investigating.
• Log structured fields, as slog does, so the output can be queried: duration, normalised statement, rows, error and the request or trace id when you have one. Adding the trace id from the context turns a slow query line into a link to the slow request.
• Group by statement shape, not text. Replace literals and numbered placeholders, then count and sum durations per shape. The sum is what matters: a 20ms query run 5,000 times a minute costs more than a 2 second one that runs twice.
• Use the server's statistics too. The pg_stat_statements extension keeps per statement call counts and total, mean and maximum time, which answers "which queries cost the most overall" better than a log of outliers. It needs shared_preload_libraries and a restart, so it was not enabled in this lab, and its view is documented in the manual. auto_explain logs the plan of slow statements; both are standard in production setups.
• Sample, do not flood. If a bad deploy makes every query slow, the log writes a line per query. Rate limit the slow log or sample it.

Pitfalls

A tracer runs on every query, so it must be cheap: no network calls, no blocking and no heavy formatting before the threshold check. The lab's check if took < threshold { return } happens before any string work for that reason. The tracer also sees statements run through the pool, but not time spent waiting for a pooled connection before the query started, so export db.Stats() wait counts separately; see connection pool settings. And log_min_duration_statement set to 0 logs everything, which is useful for ten seconds in a test and dangerous on a busy server. The server settings are documented in the PostgreSQL manual's chapter on error reporting and logging, and the tracer interface in the pgx reference.