all-in-kingsoft/hhs/GORM/16-日志与调试.md

---
tags: [GORM, Go, ORM, 日志, Debug, SlowQueryThreshold, Logger, TraceID, DryRun, ToSQL]
create time: 2026-04-28 00:00
---

# 日志与调试

## 概述

在生产环境中，你能看到的往往只有两条信息：**API 返回了什么**和**数据库执行了什么**。GORM 内置了灵活的日志系统，让你能够在不同环境下精准控制输出粒度——从「生产静默」到「开发透明」自由切换。

```mermaid
flowchart TD
    A["你的代码"] --> B["GORM SQL 生成"]
    B --> C{"Logger 配置"}
    
    C --> |Panic| D["出错了才输出<br/>生产默认值"]
    C --> |Error| E["只记录错误 SQL"]
    C --> |Warn| F["慢查询 + 错误"]
    C --> |Info| G["所有 SQL + 耗时<br/>开发推荐"]
    
    style A fill:#4FC08D,color:#fff
    style D fill:#EF4444,color:#fff
    style E fill:#F97316,color:#fff
    style F fill:#EAB308,color:#fff
    style G fill:#3B82F6,color:#fff
```

## 日志级别速览

GORM 的 `logger.Interface` 定义了四个级别：

| 级别 | 输出内容 | 适用环境 |
|------|---------|---------|
| `Silent` | 什么都不输出 | 压测、极端性能场景 |
| `Error` | 仅错误 | 稳定运行的生产环境 |
| `Warn` | 错误 + 慢查询 | 需要监控的生产环境 |
| `Info` | 所有 SQL + 参数 + 耗时 | 开发 / 调试环境 |

> [!tip] 默认级别是 `Panic`（等同于 Silent）
> GORM **不会在运行时产生任何日志**，除非你显式配置。这既保护隐私也减少磁盘 IO，但也意味着出了问题时需要临时调高日志级别来排查。

## 配置方式

### 基础用法

```go
import (
    "gorm.io/gorm/logger"
    "time"
)

newLogger := logger.New(
    logger.Config{
        SlowThreshold:             200 * time.Millisecond, // 超过 200ms 视为慢查询
        Colorful:                  true,                   // 终端彩色输出
        IgnoreRecordNotFoundError: false,                  // 记录 ErrRecordNotFound
        LogLevel:                  logger.Info,            // 日志级别
    },
)

db, err := gorm.Open(mysql.Open(dsn), &gorm.Config{
    Logger: newLogger,
})
```

### 自定义 Logger（对接 Zap / Logrus 等）

```go
// 用 Zap 替代默认日志（需 import "context"、"zap"）
type ZapLogger struct {
    logger.Interface
    zapLogger *zap.Logger
}

func (z ZapLogger) LogMode(level logger.Level) logger.Interface {
    newLogger := z
    newLogger.Interface = z.Interface.LogMode(level)
    return newLogger
}

func (z ZapLogger) Info(ctx context.Context, msg string, data ...interface{}) {
    z.zapLogger.Sugar().Infow(msg, data...)
}

func (z ZapLogger) Warn(ctx context.Context, msg string, data ...interface{}) {
    z.zapLogger.Sugar().Warnw(msg, data...)
}

func (z ZapLogger) Error(ctx context.Context, msg string, data ...interface{}) {
    z.zapLogger.Sugar().Errorw(msg, data...)
}

// 使用
zapLogger, _ := zap.NewProduction()
db, _ := gorm.Open(mysql.Open(dsn), &gorm.Config{
    Logger: ZapLogger{Interface: logger.Default, zapLogger: zapLogger},
})
```

## SQL 日志格式解析

当启用 `Info` 级别时，你会看到类似这样的输出：

```
[info] ... [0.12ms] [rows:-] SELECT * FROM users WHERE id = 1

│   │    │         │       │        │
│   │    │         │       │        └── SQL 语句
│   │    │         │       └── 影响行数 (- 表示查询不确定)
│   │    │         └── 执行耗时
│   │    └── 操作标签（SELECT/INSERT/UPDATE/DELETE）
│   └── 文件位置: src/model/user.go:15
└── 日志级别
```

### 关键指标解读

| 字段 | 含义 | 关注点 |
|------|------|--------|
| `[0.12ms]` | 单次执行耗时 | 超过 SlowThreshold 会用 WARN 标记 |
| `[rows:42]` | 影响/返回行数 | SELECT 时为正数，INSERT/UPDATE/DELETE 为影响行数 |
| `[rows:-]` | 行数未知（通常是 SELECT） | 无法提前知道，需执行后统计 |

## Debug — 临时开启详细日志

不想改全局配置的情况下，可以用 `Debug()` 方法临时对单个查询开启全量日志：

```go
// 只对这一条 SQL 输出详细信息
result := db.Debug().Where("status = ?", "active").Find(&users)
// 输出：[info] ... [1.23ms] [rows:150] SELECT * FROM users WHERE status='active'

// 对比：没有 Debug() 时可能完全看不到这条 SQL
result = db.Where("status = ?", "active").Find(&users)
// 无输出（如果 Logger 是 Silent/Error）
```

> [!tip] Debug 的实际用途
> - **快速定位问题 SQL**：在一个复杂链式调用中，找到是哪一步生成的 SQL 不对
> - **Code Review 时的验证**：确认 GORM 确实生成了预期的 SQL 语句
> - **单元测试**：临时开日志但不修改全局配置

## 慢查询监控

### 设置慢查询阈值

```go
// 超过 100ms 的 SQL 会被标记为 WARN
newLogger := logger.New(
    logger.Config{
        SlowThreshold:     100 * time.Millisecond,
        Colorful:          true,
        LogLevel:          logger.Warn,
    },
)
```

### 结合 Prometheus 做量化监控

```go
import "github.com/prometheus/client_golang/prometheus"

var queryDuration = prometheus.NewHistogramVec(
    prometheus.HistogramOpts{
        Name: "gorm_query_duration_ms",
        Help: "GORM query duration in milliseconds",
    },
    []string{"operation", "table"},
)

// 在每个请求结束后采集（简化示例）
func RecordQueryDuration(op, table string, dur time.Duration) {
    queryDuration.WithLabelValues(op, table).Observe(dur.Seconds() * 1000)
}
```

> [!question] 思考题
> 什么时候该关注慢查询？100ms、500ms 还是 1s？
> 
> > **答案**：取决于业务 SLA。对于 API 网关场景，单条 SQL 建议控制在 **50ms 以内**；对于离线批处理任务，可以放宽到秒级。关键是建立基线——先跑一周看 P95/P99 数据，再设定阈值。

## 常见调试技巧

### 打印最终 SQL（不执行）—— DryRun 模式

DryRun 模式会构建完整的 SQL 语句并输出到日志，但**不实际连接数据库执行**。这是最安全的调试方式：

```go
// DryRun 模式：构建完整 SQL 并输出，但不实际执行
db.Session(&gorm.Session{DryRun: true}).First(&user, 1)
// 输出：[info] ... [rows:0] SELECT * FROM users WHERE id = ?
// 此时你可以拿到完整的 SQL 去客户端手动验证

// 配合复杂查询链 —— 确认 Join / Preload 生成的子查询是否正确
db.Session(&gorm.Session{
    DryRun: true,
}).Preload("Orders").Joins("Profile").Where("status = ?", "active").Find(&users)
```

> [!question] DryRun vs Debug 有什么区别？
>
> | 特性 | `DryRun` | `Debug()` |
> |------|---------|-----------|
> | **是否执行 SQL** | ❌ 不执行 | ✅ 执行 |
> | **适用场景** | 审计 SQL 语法、安全审查 | 排查运行时产生的错误 SQL |
> | **性能开销** | 零（无网络 IO） | 有正常查询开销 |
> | **能否看到关联表 SQL** | ✅ Preload/Joins 都输出 | ✅ 同上 |
> >
> > **答案**：用不同的场景。想确认 "这条链式调用会生成什么 SQL" → DryRun；想确认 "生产上跑的这条 SQL 到底慢在哪里" → Debug。实际项目中推荐在 CI/CD pipeline 中跑 DryRun 做 SQL 规范校验。

#### DryRun 在单元测试中的妙用

```go
func TestUserQuerySQL(t *testing.T) {
    // 用 SQLite 内存库创建独立 DB（不需要 MySQL/PG 服务）
    sqlDB, _ := gorm.Open(sqlite.Open(":memory:"), &gorm.Config{})

    sql := sqlDB.ToSQL(func(tx *gorm.DB) *gorm.DB {
        return tx.Model(&User{}).
            Where("status = ?", "active").
            Order("created_at DESC").
            Limit(10).
            Find(&User{})
    })

    // 断言 SQL 中包含关键片段
    assert.Contains(t, sql, "WHERE status =")
    assert.Contains(t, sql, "ORDER BY created_at DESC")
    assert.Contains(t, sql, "LIMIT 10")
}
```

### 获取生成的 SQL 字符串（ToSQL）

GORM v2.4+ 提供了 `ToSQL` 方法，无需开启 DryRun 也能拿到最终的 SQL：

```go
import "gorm.io/gorm/schema"

// 构建一个独立的 DB 实例（不连接数据库）
sqlDB, _ := gorm.Open(sqlite.Open(":memory:"), &gorm.Config{})

// ToSQL 返回执行后的 SQL 字符串（不含参数展开）
sql := sqlDB.ToSQL(func(tx *gorm.DB) *gorm.DB {
    return tx.Model(&User{}).Where("name = ?", "john").Find(&User{})
})
fmt.Println(sql)
// SELECT * FROM `users` WHERE name = 'john'
```

> [!tip] 何时需要拿原始 SQL？
> - **生成 SQL 后交给他人审计**：把 ORM 生成的语句导出给 DBA 审查索引使用情况
> - **单元测试断言**：对比预期 SQL 是否符合安全规范（如是否包含未参数化的拼接）
> - **ORM 到原生迁移**：性能优化时，从 GORM 逐步替换为 Raw SQL 的过渡手段

### 日志中加入 TraceID（链路追踪）

在生产环境中，单条 SQL 日志的价值取决于能否关联到完整请求链路。通过 `context.Context` 传递 TraceID 是行业标准做法：

```go
type contextKey struct{}

// 中间件：从 HTTP Header 提取 trace_id 注入 Context
func TraceMiddleware(db *gorm.DB) func(next http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            traceID := r.Header.Get("X-Trace-Id")
            if traceID == "" {
                traceID = generateUUID() // 兜底生成
            }
            ctx := context.WithValue(r.Context(), contextKey{}, traceID)

            // 用带 trace_id 的 Context 创建新的 DB 实例
            tracedDB := db.Session(&gorm.Session{Context: ctx})
            // 这里可以将 tracedDB 存到 Context 供 handler 使用
            _ = tracedDB

            next.ServeHTTP(w, r.WithContext(ctx))
        })
    }
}

// GORM 自定义 Logger：在日志中附加 TraceID
type TraceLogger struct {
    logger.Interface
}

func (t TraceLogger) Info(ctx context.Context, msg string, data ...interface{}) {
    if traceID, ok := ctx.Value(contextKey{}).(string); ok && traceID != "" {
        msg = fmt.Sprintf("[trace:%s] %s", traceID, msg)
    }
    t.Interface.Info(ctx, msg, data...)
}
```

> [!tip] OpenTelemetry 集成要点
> 如果你已接入 OpenTelemetry，可以直接复用 SpanContext 中的 trace ID，无需自己定义 context key：
> ```go
> import "go.opentelemetry.io/otel/trace"
>
> func extractTraceID(ctx context.Context) string {
>     span := trace.SpanFromContext(ctx)
>     if span.SpanContext().IsValid() {
>         return span.SpanContext().TraceID().String()
>     }
>     return ""
> }
> ```

### 数据库方言对日志输出的影响

不同数据库驱动会影响最终生成的 SQL 语法和参数占位符：

| 驱动 | 参数占位符 | 字符串引号 | 日期格式 |
|------|-----------|-----------|---------|
| MySQL (`go-sql-driver/mysql`) | `?` | `'单引号'` | `'2026-04-28'` |
| PostgreSQL (`pgx`) | `$1`, `$2`... | `'单引号'` | `TIMESTAMP '...'` |
| SQLite (`mattn/go-sqlite3`) | `?` | `'单引号'` 或 `"双引号"` | `'...'` |
| SQL Server (`microsoft/mssql-go`) | `@p1`, `@p2`... | `'单引号'` | `DATETIME2 '...'` |

> [!note] DryRun 结果对比示例
>
> ```go
> // MySQL DryRun → SELECT * FROM users WHERE id = ?
> // PostgreSQL DryRun → SELECT * FROM users WHERE id = $1
> // SQL Server DryRun → SELECT * FROM users WHERE id = @p1
> //
> // 这意味着测试时要用对应驱动初始化 ToSQL/DryRun，否则拿到的 SQL 无法直接在其他数据库中执行。
> ```

## 常见调试技巧总结

```mermaid
flowchart TD
    Start["确定日志需求"] --> Env{"运行环境?"}
    
    Env --> |开发环境| Dev["Info 级别 + Colorful + SlowThreshold=200ms"]
    Env --> |测试环境| Test["Warn 级别 + SlowThreshold=100ms"]
    Env --> |生产环境| ProdQ{"需要实时监控?"}
    
    ProdQ --> |不需要| ProdSilent["Error 级别（默认）"]
    ProdQ --> |需要| ProdMonitor["Warn 级别 + 接入监控体系"]
    
    Dev --> Check{"特定查询需要调试?"}
    Test --> Check
    ProdMonitor --> Check
    
    Check --> |是| DebugOn["db.Debug() 临时开启"]
    Check --> |否| Done["配置完成 ✓"]
    
    style Start fill:#4FC08D,color:#fff
    style Dev fill:#3B82F6,color:#fff
    style ProdMonitor fill:#EAB308,color:#fff
    style Done fill:#A0AEC0,color:#fff
```

## 常见坑点速查

| 问题 | 原因 | 解决方案 |
|------|------|---------|
| 生产环境日志太多导致磁盘爆满 | Logger 级别设太高 | 生产用 Warn 或 Error |
| 日志中没有 TraceID 难以定位 | 没传 Context | 用 Session + Context 传递 |
| DryRun 拿到的 SQL 参数是 `?` | 预编译语句的参数未展开 | 这是正常行为，参数化查询安全性的体现 |
| Debug() 影响了其他查询的输出 | 以为会改全局配置 | `Debug()` 返回新 `*gorm.DB` 实例，不影响原对象 |
| 慢查询阈值设太低 | 正常查询也被标记为 slow | 先收集基线数据再设定合理阈值 |
| PostgreSQL 下 `?` 占位符报错 | PG 使用 `$n` 占位符 | 切换驱动或注意不同驱动的 DryRun 输出差异 |
| 自定义 Logger 丢失默认行为 | 忘记实现所有四个方法 | 继承 `logger.Interface`，只覆盖需要的方法 |
| 并发场景下 Logger 线程不安全 | 多个 goroutine 同时写日志 | 使用 Zap、Logrus 等并发安全的日志库 |

## 关联笔记

- [[01-安装与初始化]]
- [[03-CRUD 操作]]
- [[14-错误处理]]
- [[15-性能优化]]