Add query timing metadata to reporter output

This commit is contained in:
Claudio Ortolina
2026-04-10 10:30:05 +01:00
parent 27148c6507
commit 1c720c8394
2 changed files with 35 additions and 4 deletions
+3 -1
View File
@@ -50,10 +50,12 @@ Each query in the log file looks like:
```sql
-- MusicLibrary.Collection.list_records/2, at: lib/music_library/collection.ex:42
-- total=2.6ms db=2.6ms queue=0.0ms decode=0.0ms
SELECT r0."id", r0."title" FROM "records" AS r0 WHERE (r0."purchased_at" IS NOT NULL) LIMIT 20;
```
- The SQL comment shows the Elixir function and file:line that originated the query
- The first comment shows the Elixir function and file:line that originated the query
- The second comment shows timing: total, db (query execution), queue (connection wait), decode
- Parameters are fully interpolated (no `?` placeholders)
- Each query ends with `;` and is separated by a blank line
- Queries are executable — you can paste them into `sqlite3` or `mcp__tidewave__execute_sql_query`
+32 -3
View File
@@ -57,8 +57,8 @@ defmodule MusicLibrary.QueryReporter do
# sobelow_skip ["Traversal.FileModule"]
@doc false
def handle_event(@event, _measurements, metadata, file_path) do
entry = format_entry(metadata)
def handle_event(@event, measurements, metadata, file_path) do
entry = format_entry(metadata, measurements)
# Path is provided by the developer at runtime via IEx/Tidewave
File.write!(file_path, entry, [:append])
rescue
@@ -66,18 +66,47 @@ defmodule MusicLibrary.QueryReporter do
Logger.warning("QueryReporter failed to write: #{inspect(error)}")
end
defp format_entry(metadata) do
defp format_entry(metadata, measurements) do
params = metadata.cast_params || metadata.params || []
query = interpolate_query(metadata.query, params)
location = extract_source_location(metadata.stacktrace)
timing = format_timing(measurements)
IO.iodata_to_binary([
if(location, do: [location, "\n"], else: []),
timing,
"\n",
String.trim_trailing(query),
";\n\n"
])
end
defp format_timing(measurements) do
parts =
[:total_time, :query_time, :queue_time, :decode_time]
|> Enum.flat_map(fn key ->
case Map.get(measurements, key) do
nil -> []
value -> [{key, to_ms(value)}]
end
end)
label = fn
:total_time -> "total"
:query_time -> "db"
:queue_time -> "queue"
:decode_time -> "decode"
end
formatted = Enum.map_join(parts, " ", fn {key, ms} -> "#{label.(key)}=#{ms}ms" end)
"-- #{formatted}"
end
defp to_ms(native) do
us = System.convert_time_unit(native, :native, :microsecond)
Float.round(us / 1000, 1)
end
defp interpolate_query(query, []), do: query
defp interpolate_query(query, params) do