GORM Logging Slow Queries and Debug Mode in Production

The database is where most slow requests spend their time, and GORM's logger is the cheapest way to see it. It prints each statement with its duration and row count, flags slow ones and logs errors. It is also the easiest way to leak customers' email addresses into a log aggregator, or to bury real faults under a wall of "record not found". This article configures the logger four ways on PostgreSQL 18.6 and prints what each configuration emits, with the timings and file locations normalised so the output is stable.

It builds on the GORM tutorial, where logging is first mentioned. The database wide version of the same idea is the slow query log, and tracing each statement is covered in OpenTelemetry for database/sql. To find a statement that runs too often rather than too slowly, see the Preload and Joins article.

The configuration

logger.New takes a writer and a logger.Config. The fields that matter:

The lab writes to a buffer, then prints the lines with timings replaced by Nms and source locations by main.go:N, so the output is the same on every run.

package main

import (
	"bytes"
	"fmt"
	"log"
	"regexp"
	"strings"
	"time"

	"gorm.io/driver/postgres"
	"gorm.io/gorm"
	"gorm.io/gorm/logger"
)

func must(err error) {
	if err != nil {
		log.SetFlags(0)
		log.Fatal(err)
	}
}

// connect recreates a schema and returns a connection whose search_path points at it.
func connect(schema string, cfg *gorm.Config) *gorm.DB {
	base := "host=127.0.0.1 port=55432 user=postgres password=secret dbname=lab sslmode=disable"
	admin, err := gorm.Open(postgres.Open(base), &gorm.Config{Logger: logger.Discard})
	must(err)
	must(admin.Exec("drop schema if exists " + schema + " cascade").Error)
	must(admin.Exec("create schema " + schema).Error)
	if cfg == nil {
		cfg = &gorm.Config{Logger: logger.Discard}
	}
	db, err := gorm.Open(postgres.Open(base+" search_path="+schema), cfg)
	must(err)
	return db
}

type Item struct {
	ID    uint
	Name  string
	Email string
}

var timing = regexp.MustCompile(`\d+(\.\d+)?ms`)
var location = regexp.MustCompile(`[^ ]*main\.go:\d+`)

func tidy(buf *bytes.Buffer) {
	for _, l := range strings.Split(strings.TrimSpace(buf.String()), "\n") {
		if l == "" {
			continue
		}
		l = location.ReplaceAllString(l, "main.go:N")
		l = timing.ReplaceAllString(l, "Nms")
		fmt.Println("   ", strings.TrimSpace(l))
	}
	buf.Reset()
}

func main() {
	db := connect("l0724", nil)
	must(db.AutoMigrate(&Item{}))
	db.Create(&Item{Name: "a", Email: "[email protected]"})

	var buf bytes.Buffer
	lg := logger.New(log.New(&buf, "", 0), logger.Config{
		SlowThreshold:             100 * time.Millisecond,
		LogLevel:                  logger.Warn,
		IgnoreRecordNotFoundError: true,
		Colorful:                  false,
	})
	db.Logger = lg

	fmt.Println("1. warn level, fast query: nothing logged")
	db.Where("name = ?", "a").Find(&[]Item{})
	tidy(&buf)

	fmt.Println("2. a slow query is logged with SLOW SQL:")
	db.Exec("select pg_sleep(0.15)")
	tidy(&buf)

	fmt.Println("3. an error is logged:")
	db.Exec("select * from missing_table")
	tidy(&buf)

	fmt.Println("4. record not found is quiet when ignored:")
	db.First(&Item{}, 999)
	tidy(&buf)

	fmt.Println("5. info level logs every statement, with values:")
	db.Logger = lg.LogMode(logger.Info)
	db.Where("email = ?", "[email protected]").Find(&[]Item{})
	tidy(&buf)

	fmt.Println("6. ParameterizedQueries keeps values out of the log:")
	db.Logger = logger.New(log.New(&buf, "", 0), logger.Config{LogLevel: logger.Info, ParameterizedQueries: true})
	db.Where("email = ?", "[email protected]").Find(&[]Item{})
	tidy(&buf)

	fmt.Println("7. Debug() raises one call to info level:")
	db.Logger = lg
	db.Debug().Where("name = ?", "a").Find(&[]Item{})
	tidy(&buf)
}

1. warn level, fast query: nothing logged
2. a slow query is logged with SLOW SQL:
    main.go:N SLOW SQL >= Nms
    [Nms] [rows:1] select pg_sleep(0.15)
3. an error is logged:
    main.go:N ERROR: relation "missing_table" does not exist (SQLSTATE 42P01)
    [Nms] [rows:0] select * from missing_table
4. record not found is quiet when ignored:
5. info level logs every statement, with values:
    main.go:N
    [Nms] [rows:1] SELECT * FROM "items" WHERE email = '[email protected]'
6. ParameterizedQueries keeps values out of the log:
    main.go:N
    [Nms] [rows:1] SELECT * FROM "items" WHERE email = $1$
7. Debug() raises one call to info level:
    main.go:N
    [Nms] [rows:1] SELECT * FROM "items" WHERE name = 'a'

What each level prints

Warn, fast query. Block 1 ran a Find at the Warn level. Nothing was printed. That is the right default for production: a logger that writes a line for every query turns a busy service into a log shipping problem, and the lines you want are lost in the volume.

Warn, slow query. Block 2 ran select pg_sleep(0.15) against a 100 ms threshold. Two lines were logged: main.go:N SLOW SQL >= Nms and then [Nms] [rows:1] select pg_sleep(0.15). The first names the file and line that issued the call (useful for finding the caller), the second gives the elapsed time, the row count and the SQL. The threshold is a policy choice. Start near your p99 for the endpoint, and lower it as you fix things. A threshold of 200 ms on an API that targets 100 ms hides most of the problem.

Errors. Block 3 ran a query on a table that does not exist. The log has the PostgreSQL message with its SQLSTATE, relation "missing_table" does not exist (SQLSTATE 42P01), followed by the statement. This is logged even if your handler swallows the error, which is a mixed blessing: it exposes failures that were hidden, and it duplicates errors the handler also logs. Decide where database errors are logged, once.

Record not found. Block 4 ran First(&Item{}, 999). With IgnoreRecordNotFoundError: true, nothing was logged. Without it, every miss writes an ERROR line with record not found, and a service whose clients probe for ids fills its error log with normal behaviour. Turn it on, and handle the absence in the code that asked.

Values in the log

Block 5 raised the level to Info, which logs every statement. The line was:

[Nms] [rows:1] SELECT * FROM "items" WHERE email = '[email protected]'

The value is in the log. GORM renders the placeholders with the real arguments so the line can be pasted into psql, which is convenient while developing and a privacy problem in production. Emails, tokens, names and anything else the query binds is written to your log files, retained by your log vendor, and visible to anyone with read access to logs.

Block 6 sets ParameterizedQueries: true. The statement became SELECT * FROM "items" WHERE email = $1$ and the value is gone. Use this setting anywhere logs leave the machine. (The trailing character is part of how GORM renders it; the point is that the argument is not in the line.) You lose the ability to copy a statement into psql; you keep the shape of the query, which is what you need to find a slow one, and the timing.

Even with parameterised output, a slow query line can include a Raw statement you built by concatenation, with its values. Concatenated SQL is a separate problem (see raw SQL); the logger cannot tell which parts are values.

One call at a time with Debug

Block 7 swapped back to the Warn logger and called db.Debug().Where(...). The statement was logged although the connection was at Warn. Debug() returns a session whose logger is Info for that call only. Use it while investigating a single path, and delete it afterwards. A Debug() left in code is an unconditional log line for every request through that function, with values.

Production setup

A configuration that works for most services:

newLogger := logger.New(
	log.New(os.Stdout, "", log.LstdFlags),
	logger.Config{
		SlowThreshold:             200 * time.Millisecond,
		LogLevel:                  logger.Warn,
		IgnoreRecordNotFoundError: true,
		ParameterizedQueries:      true,
		Colorful:                  false,
	},
)
db, err := gorm.Open(dialector, &gorm.Config{Logger: newLogger})

Then adjust per environment: Info locally, Warn in staging and production. Read the level from configuration, so that changing it during an incident does not need a deploy.

Structured logs

The built in logger writes plain text. A service that ships JSON logs wants fields instead: duration, rows, SQL, caller. GORM's logger.Interface has four methods (LogMode, Info, Warn, Error) plus Trace, which receives the begin time and a function that returns the SQL and row count. Implement that interface over slog and the slow query becomes a record with duration_ms, rows, sql and error attributes, ready for a query in your log backend. Write the adapter once, with the slow threshold and the not found rule inside it, and test it with a buffer as the lab does. Be careful with the SQL attribute: log the parameterised form (fc() returns the rendered statement; use db.Dialector.Explain with avoid set or log only the template) so values stay out.

What the logger cannot tell you

• Statements that never finish. Trace runs after the call returns. A query stuck on a lock logs nothing until it ends, and a cancelled one logs the error. Use pg_stat_activity and a statement timeout for hung queries.
• The plan. A slow line says the query is slow, and EXPLAIN says why (guide). Copy the statement from a development log and run it with EXPLAIN (ANALYZE, BUFFERS).
• Aggregate cost. A query that takes 3 ms and runs 400 times per request never trips the threshold. Metrics and traces see it; a slow log does not.
• Everything outside GORM. Calls through db.DB() or Raw on the underlying pool are not routed through the logger.

For the database side, log_min_duration_statement in PostgreSQL logs slow statements from every client, with no change to the application, and it is the better source of truth when several services share a database.

Checklist

• Build the logger with logger.New, Warn level, a threshold near your target latency.
• Set IgnoreRecordNotFoundError and ParameterizedQueries in production.
• Use Debug() for one call and remove it.
• Adapt logger.Interface to your structured logger if you ship JSON.
• Keep the server's log_min_duration_statement as the cross check.

The logger options are documented in the GORM logger guide, and the server side setting in the PostgreSQL error reporting and logging reference.