feat: log the inspector's query call tree under --debug (#285, #644, #654)

[tianzhou]

Summary

--debug now logs a call tree of every catalog query the inspector issues, one line per BuildIR step, so a slow dump or plan over a high-latency connection can be diagnosed from the CLI alone.

• Every query goes through a thin tracingDB wrapper that attributes it to the step carried in the context (new ir/trace.go).
• BuildIR steps are named; each sequential step, each concurrent group, and each step inside a group is a node with its query count, summed query time, and wall time.
• A step that issues more than one query is broken down by query shape: the sqlc query name, or the collapsed leading SQL for ad hoc statements. Steps inside a concurrent group are listed heaviest first.
• No per-query log lines, so a 3,000-query inspection still prints about 60 lines. Output is unchanged without --debug; the cost with it off is a mutex and a map update per query.

Example against the employee fixture with grants to two roles (7 tables):

inspector: BuildIR schema=public                              queries=164 query_time=411ms wall=61ms
inspector:   independent objects (concurrent)                 queries=125 query_time=274ms wall=49ms
inspector:     privileges                                     queries=112 query_time=48ms wall=49ms
inspector:       SELECT rolname FROM pg_roles WHERE oid = $1  queries=110 query_time=14ms
inspector:       GetPrivilegesForSchema                       queries=1   query_time=33ms
inspector:       GetRevokedDefaultPrivilegesForSchema         queries=1   query_time=1ms
inspector:     types                                          queries=5   ...
inspector:   table details (concurrent)                       queries=24  query_time=125ms wall=48ms
inspector:     constraints                                    queries=22  query_time=47ms wall=48ms
inspector:       SELECT kcu.ordinal_position FROM information_schema.key_column_usage k...  queries=20
inspector:       GetConstraintsForSchema                      queries=1

The two per-row lookups behind #644 / #654 are visible by name with their counts. query_time is the sum of round trips (send to first response); wall is elapsed time for the node, so a step with large query_time and small wall is being hidden by parallel siblings.

Refs #285 (original ask for query-level diagnostics), #644, #654. This is observability only; the N+1 fix itself is tracked in #644.

Test plan

• New unit tests in ir/trace_test.go: span attribution and nesting, shape keys, heaviest-first ordering, concurrent recording under -race
• go test ./ir/... -race
• PGSCHEMA_TEST_FILTER=create_table/add_column go test ./cmd -run TestPlanAndApply
• go test ./cmd/dump -run 'TestDumpCommand_Employee|TestDumpCommand_Sakila'
• go vet ./...
• Manual: pgschema --debug dump --schema public against a local Postgres produces the tree above

🤖 Generated with Claude Code

[Copilot]

🟢 Approval recommended

Static review identified no blocking correctness or synchronization issues; tests were not executed.

0 open findings

What changed in this PR

Adds inspector query tracing under --debug to help diagnose slow schema inspection without changing query behavior.

Changes:

• Records query counts, timings, and shapes in a named BuildIR call tree.
• Adds tests for attribution, nesting, log ordering, and concurrent recording.

File	Description
ir/​trace.go	Implements query wrapping, span aggregation, and debug logging.
ir/​trace_test.go	Tests trace attribution, formatting, and concurrency.
ir/​inspector.go	Integrates tracing into sequential and concurrent inspection steps.

🧠 Review effort: Balanced

---

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[greptile-apps]

Confidence Score: 5/5

[Medium impact] The PR appears safe to merge.

Summary

Adds a query call tree to inspection logs under --debug.

• The inspector logs a query tree for each BuildIR call in debug mode.

No actionable issues found. Tests were not run during this review.
Acknowledged design: tianzhou states that query_time stops at the first response rather than including later row reads.

Diagram

%%{init: {'theme': 'neutral'}}%%
flowchart TD
  A[BuildIR root] --> B[Sequential steps]
  A --> C[Concurrent groups]
  C --> D[Named steps]
  B --> E[tracingDB]
  D --> E
  E --> F[PostgreSQL]
  E --> G[Count and time queries by shape]
  G --> H[Log completed tree when debug is enabled]

Loading

_{Reviews (1) · Last reviewed commit: "feat: log the inspector's query call tre..." · Reviewed by Greptile}