internal/render/render.go - master - rustwizard/pgtrace

internal/render/render.go
427 строк10 KB
Rust Wizard
feat: include the blocking query in insight output
08 авг 2026, 11:30
08 авг 2026, 11:304e57a23
// Package render formats syscall events as a colored terminal timeline.
package render

import (
	"fmt"
	"io"
	"sort"
	"strings"
	"time"

	"github.com/rustwizard/pgtrace/internal/agg"
	"github.com/rustwizard/pgtrace/internal/bpf"
	"github.com/rustwizard/pgtrace/internal/pgstat"
)

const (
	ansiReset   = "\033[0m"
	ansiCyan    = "\033[36m"
	ansiGreen   = "\033[32m"
	ansiYellow  = "\033[33m"
	ansiRed     = "\033[31m"
	ansiDim     = "\033[2m"
	maxQueryLen = 120
)

// Event writes one timeline line for ev to w.
//
// Layout: [15:04:05.123] pid=1234(bgwriter) fsync 15.2ms query="..."
// Duration is colored green (<10ms), yellow (10-50ms) or red (>50ms).
func Event(w io.Writer, ev bpf.Event, act pgstat.Activity, now time.Time) error {
	//nolint:gosec // kernel duration always fits in int64 nanoseconds
	dur := time.Duration(ev.DurationNs)
	_, err := fmt.Fprintf(w, "%s[%s]%s pid=%d%s %s%-9s%s %s%9s%s %s\n",
		ansiDim, now.Format("15:04:05.000"), ansiReset,
		ev.PID,
		backendTag(act),
		ansiCyan, bpf.SyscallName(ev.SyscallID), ansiReset,
		durationColor(dur), formatDuration(dur), ansiReset,
		formatQuery(act),
	)

	return err
}

// backendTag returns a dim tag like "(bgwriter)" for background processes,
// or "" for client backends.
func backendTag(a pgstat.Activity) string {
	if !a.IsBackground() || a.BackendType == "" {
		return ""
	}

	short := a.BackendType
	if len(short) > 12 {
		short = short[:12]
	}

	return ansiDim + "(" + short + ")" + ansiReset
}

// WaitEvent writes one off-CPU wait line to w.
//
// Layout: [15:04:05.123] pid=1234 wait=LWLock 15.2ms query="SELECT ...".
func WaitEvent(w io.Writer, ev bpf.OffCPUEvent, act pgstat.Activity, now time.Time) error {
	//nolint:gosec // kernel duration always fits in int64 nanoseconds
	dur := time.Duration(ev.DurationNs)
	_, err := fmt.Fprintf(w, "%s[%s]%s pid=%d%s %s%-9s%s %s%9s%s %s\n",
		ansiDim, now.Format("15:04:05.000"), ansiReset,
		ev.PID,
		backendTag(act),
		ansiYellow, "wait="+waitDisplayName(ev.WaitType), ansiReset,
		durationColor(dur), formatDuration(dur), ansiReset,
		formatQuery(act),
	)

	return err
}

// waitDisplayName maps an internal wait type to a short display name.
func waitDisplayName(wt string) string {
	if n, ok := waitNames[wt]; ok {
		return n
	}

	return wt
}

func durationColor(d time.Duration) string {
	switch {
	case d > 50*time.Millisecond:
		return ansiRed
	case d > 10*time.Millisecond:
		return ansiYellow
	default:
		return ansiGreen
	}
}

func formatDuration(d time.Duration) string {
	if d < time.Millisecond {
		return fmt.Sprintf("%.0fus", float64(d.Microseconds()))
	}

	return fmt.Sprintf("%.1fms", float64(d.Microseconds())/1000)
}

func formatQuery(a pgstat.Activity) string {
	if a.Query == "" {
		if a.State != "" {
			return ansiDim + "state=" + a.State + ansiReset
		}

		return ansiDim + "query=?" + ansiReset
	}

	q := strings.Join(strings.Fields(a.Query), " ")
	if len(q) > maxQueryLen {
		q = q[:maxQueryLen] + "..."
	}

	return `query="` + q + `"`
}

// hints maps syscall names to a tuning hint shown when the syscall
// dominates the window.
var hints = map[string]string{
	"fsync":     "check wal_sync_method and fsync settings",
	"fdatasync": "check wal_sync_method and fsync settings",
	"pread64":   "check shared_buffers and cache hit ratio (pg_buffercache)",
	"read":      "check shared_buffers and cache hit ratio (pg_buffercache)",
	"pwrite64":  "check checkpoint tuning (checkpoint_timeout, max_wal_size)",
	"write":     "check checkpoint tuning (checkpoint_timeout, max_wal_size)",
	"futex":     "lock contention: check pg_locks and LWLock waits (pg_stat_activity.wait_event)",
	"nanosleep": "check pg_sleep / client-side throttling",
	"openat":    "temp file I/O detected: check work_mem and temp_buffers (files spilled to disk)",
	"sendto":    "network I/O to clients: check client-side latency and connection pooling",
	"recvfrom":  "network I/O from clients: check client-side latency and connection pooling",
}

// Insight describes a dominant bottleneck in one window.
type Insight struct {
	// Kind is "wait" or "syscall".
	Kind string
	// Name is the display name of the dominant wait type or syscall.
	Name string
	// Metric is the machine-readable key (wait type or syscall name).
	Metric string
	// Pct is the share of non-idle wait time (wait) or total syscall time.
	Pct int
	// Query is the normalized query that contributed the most, "" if unknown.
	Query string
	// Hint is a tuning suggestion.
	Hint string
}

// InsightThreshold is the share above which an insight fires.
const InsightThreshold = 0.5

// ComputeInsight determines whether one wait type or syscall dominates the
// window. Idle waits are normal and never trigger an insight. Returns nil
// when nothing dominates.
func ComputeInsight(stats map[uint32]agg.Stats, waits map[string]agg.WaitStat) *Insight {
	if len(waits) > 0 {
		return computeWaitInsight(waits)
	}

	if len(stats) == 0 {
		return nil
	}

	ids := make([]uint32, 0, len(stats))

	var total float64

	for id, s := range stats {
		ids = append(ids, id)
		total += s.TotalMs
	}

	if total <= 0 {
		return nil
	}

	sort.Slice(ids, func(i, j int) bool {
		return stats[ids[i]].TotalMs > stats[ids[j]].TotalMs
	})

	top := stats[ids[0]]
	if top.TotalMs/total <= InsightThreshold {
		return nil
	}

	name := bpf.SyscallName(ids[0])

	hint := "inspect pg_stat_activity and server config"
	if h, ok := hints[name]; ok {
		hint = h
	}

	q, _ := top.TopQuery()

	return &Insight{
		Kind:   "syscall",
		Name:   name,
		Metric: name,
		Pct:    int(top.TotalMs / total * 100),
		Query:  q,
		Hint:   hint,
	}
}

// computeWaitInsight returns the dominant non-idle wait type, or nil.
func computeWaitInsight(waits map[string]agg.WaitStat) *Insight {
	nonIdle := 0.0

	for wt, ws := range waits {
		if wt != "idle" {
			nonIdle += ws.TotalMs
		}
	}

	if nonIdle <= 0 {
		return nil
	}

	topType, top := "", 0.0

	for wt, ws := range waits {
		if wt == "idle" {
			continue
		}

		if ws.TotalMs > top {
			topType, top = wt, ws.TotalMs
		}
	}

	if topType == "" || top/nonIdle <= InsightThreshold {
		return nil
	}

	name := waitNames[topType]
	if name == "" {
		name = topType
	}

	topWait := waits[topType]

	return &Insight{
		Kind:   "wait",
		Name:   name,
		Metric: topType,
		Pct:    int(top / nonIdle * 100),
		Query:  topWaitQuery(topWait),
		Hint:   waitHints[topType],
	}
}

// writeInsight prints an INSIGHT line for ins.
func writeInsight(w io.Writer, ins *Insight) error {
	line := "\n" + ansiRed + "INSIGHT:" + ansiReset + " " + ins.Name +
		fmt.Sprintf(" accounts for %d%% of %s in this window. %s.", ins.Pct, insightSubject(ins), ins.Hint)
	if ins.Query != "" && ins.Query != "?" {
		line += " Top: " + ins.Query
	}

	_, err := fmt.Fprintln(w, line)

	return err
}

func insightSubject(ins *Insight) string {
	if ins.Kind == "wait" {
		return "non-idle off-CPU time"
	}

	return "syscall time"
}

// Summary writes a window aggregation report to w.
//
// === Window 15:04:05-15:04:15 ===
// fsync:    47 calls, avg 12.3ms, max 45.2ms
//
//	Top query: UPDATE pgbench_accounts... (42x)
//
// INSIGHT: fsync accounts for 73% of syscall time. Check wal_sync_method and fsync settings.
func Summary(w io.Writer, start, end time.Time, stats map[uint32]agg.Stats, waits map[string]agg.WaitStat) error {
	if _, err := fmt.Fprintf(w, "%s=== Window %s-%s ===%s\n",
		ansiYellow, start.Format("15:04:05"), end.Format("15:04:05"), ansiReset); err != nil {
		return err
	}

	if len(stats) == 0 && len(waits) == 0 {
		_, err := fmt.Fprintf(w, "%sno events%s\n", ansiDim, ansiReset)
		return err
	}

	if len(waits) > 0 {
		if err := renderWaits(w, waits); err != nil {
			return err
		}
	}

	if err := renderSyscalls(w, stats); err != nil {
		return err
	}

	if ins := ComputeInsight(stats, waits); ins != nil {
		return writeInsight(w, ins)
	}

	return nil
}

// renderSyscalls prints per-syscall stats and their top queries, returning the
// total syscall time in the window.
func renderSyscalls(w io.Writer, stats map[uint32]agg.Stats) error {
	ids := make([]uint32, 0, len(stats))

	for id := range stats {
		ids = append(ids, id)
	}

	sort.Slice(ids, func(i, j int) bool {
		return stats[ids[i]].TotalMs > stats[ids[j]].TotalMs
	})

	for _, id := range ids {
		s := stats[id]
		if _, err := fmt.Fprintf(w, "%s%-9s%s %4d calls, avg %6.1fms, max %6.1fms\n",
			ansiCyan, bpf.SyscallName(id), ansiReset,
			s.Count, s.TotalMs/float64(s.Count), s.MaxMs); err != nil {
			return err
		}

		entries := s.TopQueries(3)
		for i, e := range entries {
			if e.Query == "" {
				continue
			}

			label := "Top query:"
			if i > 0 {
				label = fmt.Sprintf("#%d", i+1)
			}

			if _, err := fmt.Fprintf(w, "  %s%-11s%s %s (%dx)\n", ansiDim, label, ansiReset, e.Query, e.Count); err != nil {
				return err
			}
		}
	}

	return nil
}

// waitNames is the display name for each wait type.
var waitNames = map[string]string{
	"lwlock":    "LWLock",
	"lock":      "Lock",
	"io":        "I/O",
	"wal_write": "WAL write",
	"network":   "Network",
	"idle":      "Idle",
	"other":     "Other",
}

// renderWaits prints the per-wait-type breakdown for a window, sorted by
// total time descending.
func renderWaits(w io.Writer, waits map[string]agg.WaitStat) error {
	types := make([]string, 0, len(waits))

	var total float64

	for wt, ws := range waits {
		types = append(types, wt)
		total += ws.TotalMs
	}

	sort.Slice(types, func(i, j int) bool {
		return waits[types[i]].TotalMs > waits[types[j]].TotalMs
	})

	for _, wt := range types {
		ws := waits[wt]

		name := waitNames[wt]
		if name == "" {
			name = wt
		}

		if _, err := fmt.Fprintf(w, "%s%-9s%s %6.1fms wait (%d%% of wait time)\n",
			ansiCyan, name, ansiReset, ws.TotalMs, int(ws.TotalMs/total*100)); err != nil {
			return err
		}

		top := topWaitQuery(ws)
		if top != "" {
			if _, err := fmt.Fprintf(w, "  %sTop wait:%s %s\n", ansiDim, ansiReset, top); err != nil {
				return err
			}
		}
	}

	return nil
}

// topWaitQuery returns the query that waited the longest in a wait type.
func topWaitQuery(ws agg.WaitStat) string {
	top, best := "", 0.0
	for q, ms := range ws.Queries {
		if ms > best {
			top, best = q, ms
		}
	}

	return top
}

// waitHints gives a tuning hint per wait type.
var waitHints = map[string]string{
	"lwlock":    "check pg_locks and shared_buffers; consider scaling connections",
	"lock":      "check pg_locks for conflicting row/table locks (blocking sessions)",
	"io":        "check disk latency, work_mem spills and cache hit ratio",
	"wal_write": "check wal_sync_method, wal_buffers and disk fsync latency",
	"network":   "check client-side latency and connection pooling",
	"other":     "inspect the kernel stack via /api/v1/windows",
}