Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: telemetry #48

Merged
merged 2 commits into from
Nov 29, 2023
Merged

feat: telemetry #48

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
3dfab66
feat: telemetry
mhanberg Nov 29, 2023
76c7d78
fixup! feat: telemetry
mhanberg Nov 29, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
105 changes: 95 additions & 10 deletions lib/gen_lsp.ex
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -205,7 +205,16 @@ defmodule GenLSP do
'''
@spec notify(GenLSP.LSP.t(), notification :: any()) :: :ok
def notify(%{buffer: buffer}, notification) do
GenLSP.Buffer.outgoing(buffer, dump!(notification.__struct__.schematic(), notification))
Logger.debug("sent notification server -> client #{notification.method}",
method: notification.method
)

:telemetry.span([:gen_lsp, :notify, :server], %{}, fn ->
result =
GenLSP.Buffer.outgoing(buffer, dump!(notification.__struct__.schematic(), notification))

{result, %{method: notification.method}}
end)
end

@doc ~S'''
Expand All @@ -222,7 +231,17 @@ defmodule GenLSP do
'''
@spec request(GenLSP.LSP.t(), request :: any()) :: any()
def request(%{buffer: buffer}, request) do
GenLSP.Buffer.outgoing_sync(buffer, dump!(request.__struct__.schematic(), request))
Logger.debug("sent request server -> client #{request.method}",
id: request.id,
method: request.method
)

:telemetry.span([:gen_lsp, :request, :server], %{}, fn ->
result =
GenLSP.Buffer.outgoing_sync(buffer, dump!(request.__struct__.schematic(), request))

{result, %{id: request.id, method: request.method}}
end)
end

defp write_debug(device, event, name) do
Expand All @@ -237,15 +256,22 @@ defmodule GenLSP do
{:request, from, request} ->
deb = :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:in, :request, from})

start = System.system_time(:microsecond)
:telemetry.execute([:gen_lsp, :request, :client, :start], %{})

attempt(
lsp,
"Last message received: handle_request #{inspect(request)}",
[:gen_lsp, :request, :client],
fn ->
{:ok, %{id: id} = req} = GenLSP.Requests.new(request)

# GenLSP.log(lsp, :log, "[GenLSP] Processing #{inspect(req.__struct__)}")
result =
:telemetry.span([:gen_lsp, :handle_request], %{method: req.method}, fn ->
{lsp.mod.handle_request(req, lsp), %{}}
end)

case lsp.mod.handle_request(req, lsp) do
case result do
{:reply, reply, %LSP{} = lsp} ->
response_key =
case reply do
Expand All @@ -259,52 +285,109 @@ defmodule GenLSP do
response_key => dump!(req.__struct__.result(), reply)
}

deb = :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:out, :request, from})
deb =
:sys.handle_debug(deb, &write_debug/3, __MODULE__, {:out, :request, from})

GenLSP.Buffer.outgoing(lsp.buffer, packet)

duration = System.system_time(:microsecond) - start

Logger.debug(
"handled request client -> server #{req.method} in #{format_time(duration)}",
id: req.id,
method: req.method
)

:telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})

loop(lsp, parent, deb)

{:noreply, lsp} ->
duration = System.system_time(:microsecond) - start

Logger.debug(
"handled request client -> server #{req.method} in #{format_time(duration)}",
id: req.id,
method: req.method
)

:telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})

loop(lsp, parent, deb)
end
end
)

{:notification, from, notification} ->
deb = :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:in, :notification, from})
start = System.system_time(:microsecond)
:telemetry.execute([:gen_lsp, :notification, :client, :start], %{})

attempt(
lsp,
"Last message received: handle_notification #{inspect(notification)}",
[:gen_lsp, :notification, :client],
fn ->
{:ok, note} = GenLSP.Notifications.new(notification)

# GenLSP.log(lsp, :log, "[GenLSP] Processing #{inspect(note.__struct__)}")
result =
:telemetry.span([:gen_lsp, :handle_notification], %{method: note.method}, fn ->
{lsp.mod.handle_notification(note, lsp), %{}}
end)

case lsp.mod.handle_notification(note, lsp) do
case result do
{:noreply, %LSP{} = lsp} ->
duration = System.system_time(:microsecond) - start

Logger.debug(
"handled notification client -> server #{note.method} in #{format_time(duration)}",
method: note.method
)

:telemetry.execute([:gen_lsp, :notification, :client, :stop], %{
duration: duration
})

loop(lsp, parent, deb)
end
end
)

message ->
start = System.system_time(:microsecond)
:telemetry.execute([:gen_lsp, :info, :start], %{})

attempt(
lsp,
"Last message received: handle_info #{inspect(message)}",
[:gen_lsp, :info],
fn ->
case lsp.mod.handle_info(message, lsp) do
result =
:telemetry.span([:gen_lsp, :handle_info], %{}, fn ->
{lsp.mod.handle_info(message, lsp), %{}}
end)

case result do
{:noreply, %LSP{} = lsp} ->
duration = System.system_time(:microsecond) - start
:telemetry.execute([:gen_lsp, :info, :stop], %{duration: duration})
loop(lsp, parent, deb)
end
end
)
end
end

@spec attempt(LSP.t(), String.t(), (-> any())) :: no_return()
defp attempt(lsp, message, callback) do
defp format_time(time) when time < 1000 do
"#{time}µs"
end

defp format_time(time) do
"#{System.convert_time_unit(time, :microsecond, :millisecond)}ms"
end

@spec attempt(LSP.t(), String.t(), list(atom()), (-> any())) :: no_return()
defp attempt(lsp, message, prefix, callback) do
callback.()
rescue
e ->
Expand All @@ -317,6 +400,8 @@ defmodule GenLSP do

"""

:telemetry.execute(prefix ++ [:exception], %{message: message})

error(lsp, message)
Logger.error(message)

Expand Down
43 changes: 27 additions & 16 deletions lib/gen_lsp/buffer.ex
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,35 +71,46 @@ defmodule GenLSP.Buffer do
end

def handle_call({:outgoing_sync, %{"id" => id} = packet}, from, state) do
:ok = state.comm.write(Jason.encode!(packet), state.comm_data)
:telemetry.span([:gen_lsp, :buffer, :outgoing], %{kind: :sync}, fn ->
:ok = state.comm.write(Jason.encode!(packet), state.comm_data)
{:ok, %{}}
end)

{:noreply, %{state | awaiting_response: Map.put(state.awaiting_response, id, from)}}
end

@doc false
def handle_cast({:incoming, packet}, %{lsp: lsp} = state) do
state =
case Jason.decode!(packet) do
%{"id" => id, "result" => result} when is_map_key(state.awaiting_response, id) ->
{from, awaiting_response} = Map.pop(state.awaiting_response, id)
GenServer.reply(from, result)

%{state | awaiting_response: awaiting_response}

%{"id" => _} = request ->
GenLSP.request_server(lsp, request)
state
:telemetry.span([:gen_lsp, :buffer, :incoming], %{}, fn ->
state =
case Jason.decode!(packet) do
%{"id" => id, "result" => result} when is_map_key(state.awaiting_response, id) ->
{from, awaiting_response} = Map.pop(state.awaiting_response, id)
GenServer.reply(from, result)

%{state | awaiting_response: awaiting_response}

%{"id" => _} = request ->
GenLSP.request_server(lsp, request)
state

notification ->
GenLSP.notify_server(lsp, notification)
state
end

notification ->
GenLSP.notify_server(lsp, notification)
state
end
{state, %{}}
end)

{:noreply, state}
end

def handle_cast({:outgoing, packet}, state) do
:ok = state.comm.write(Jason.encode!(packet), state.comm_data)
:telemetry.span([:gen_lsp, :buffer, :outgoing], %{kind: :async}, fn ->
:ok = state.comm.write(Jason.encode!(packet), state.comm_data)
{:ok, %{}}
end)

{:noreply, state}
end
Expand Down
Loading