fix: improve ErlSysMon logging for processes (#1540)

Include initial_call, ancestors, registered_name, message_queue_len and total_heap_size

Also bump long_schedule and long_gc

Author: edgurgel

lib/realtime/monitoring/erl_sys_mon.ex

@@ -10,8 +10,8 @@ defmodule Realtime.ErlSysMon do
   @defaults [
     :busy_dist_port,
     :busy_port,
-    {:long_gc, 250},
-    {:long_schedule, 100},
+    {:long_gc, 500},
+    {:long_schedule, 500},
     {:long_message_queue, {0, 1_000}}
   ]
 
@@ -24,8 +24,36 @@ defmodule Realtime.ErlSysMon do
     {:ok, []}
   end
 
+  def handle_info({:monitor, pid, _type, _meta} = msg, state) when is_pid(pid) do
+    log_process_info(msg, pid)
+    {:noreply, state}
+  end
+
   def handle_info(msg, state) do
-    Logger.error("#{__MODULE__} message: " <> inspect(msg))
+    Logger.warning("#{__MODULE__} message: " <> inspect(msg))
     {:noreply, state}
   end
+
+  defp log_process_info(msg, pid) do
+    pid_info =
+      pid
+      |> Process.info(:dictionary)
+      |> case do
+        {:dictionary, dict} when is_list(dict) ->
+          {List.keyfind(dict, :"$initial_call", 0), List.keyfind(dict, :"$ancestors", 0)}
+
+        other ->
+          other
+      end
+
+    extra_info = Process.info(pid, [:registered_name, :message_queue_len, :total_heap_size])
+
+    Logger.warning(
+      "#{__MODULE__} message: " <>
+        inspect(msg) <> "|\n process info: #{inspect(pid_info)} #{inspect(extra_info)}"
+    )
+  rescue
+    _ ->
+      Logger.warning("#{__MODULE__} message: " <> inspect(msg))
+  end
 end

mix.exs

@@ -4,7 +4,7 @@ defmodule Realtime.MixProject do
   def project do
     [
       app: :realtime,
-      version: "2.51.1",
+      version: "2.51.2",
       elixir: "~> 1.17.3",
       elixirc_paths: elixirc_paths(Mix.env()),
       start_permanent: Mix.env() == :prod,

test/realtime/monitoring/erl_sys_mon_test.exs

@@ -5,16 +5,25 @@ defmodule Realtime.Monitoring.ErlSysMonTest do
 
   describe "system monitoring" do
     test "logs system monitor events" do
-      start_supervised!({ErlSysMon, config: [{:long_message_queue, {1, 10}}]})
+      start_supervised!({ErlSysMon, config: [{:long_message_queue, {1, 100}}]})
 
-      assert capture_log(fn ->
-               Task.async(fn ->
-                 Enum.map(1..1000, &send(self(), &1))
-                 # Wait  for ErlSysMon to notice
-                 Process.sleep(4000)
-               end)
-               |> Task.await()
-             end) =~ "Realtime.ErlSysMon message:"
+      log =
+        capture_log(fn ->
+          Task.async(fn ->
+            Process.register(self(), TestProcess)
+            Enum.map(1..1000, &send(self(), &1))
+            # Wait  for ErlSysMon to notice
+            Process.sleep(4000)
+          end)
+          |> Task.await()
+        end)
+
+      assert log =~ "Realtime.ErlSysMon message:"
+      assert log =~ "$initial_call\", {Realtime.Monitoring.ErlSysMonTest"
+      assert log =~ "ancestors\", [#{inspect(self())}]"
+      assert log =~ "registered_name: TestProcess"
+      assert log =~ "message_queue_len: "
+      assert log =~ "total_heap_size: "
     end
   end
 end