diff --git a/.claude/skills/query-reporter/SKILL.md b/.claude/skills/query-reporter/SKILL.md index 22736832..9f6912a6 100644 --- a/.claude/skills/query-reporter/SKILL.md +++ b/.claude/skills/query-reporter/SKILL.md @@ -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` diff --git a/lib/music_library/query_reporter.ex b/lib/music_library/query_reporter.ex index 0525cb4b..5bfb5281 100644 --- a/lib/music_library/query_reporter.ex +++ b/lib/music_library/query_reporter.ex @@ -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