Repository: honeybadger-io/honeybadger-elixir
Pull request #603 (2025-04-04 13:05:50)

Use microseconds for measurements
Milliseconds are a bit too imprecise for some telemetry events.

I had considered converting to a millisecond float, but I opted to stick to a microsecond integer, as that is more idiomatic erlang. Insights can handle microseconds just as well as milliseconds as long as the integer fits into 64bit space.


Patch:
diff --git a/lib/honeybadger/insights/base.ex b/lib/honeybadger/insights/base.ex
index 7dde6c4..3d4cc92 100644
--- a/lib/honeybadger/insights/base.ex
+++ b/lib/honeybadger/insights/base.ex
@@ -105,7 +105,7 @@ defmodule Honeybadger.Insights.Base do
             acc
 
           {key, val}, acc when key in @time_keys ->
-            Map.put(acc, key, System.convert_time_unit(val, :native, :millisecond))
+            Map.put(acc, key, System.convert_time_unit(val, :native, :microsecond))
 
           {key, val}, acc ->
             Map.put(acc, key, val)


Test patch:
diff --git a/test/honeybadger/insights/absinthe_test.exs b/test/honeybadger/insights/absinthe_test.exs
index 39cd310..833c8d4 100644
--- a/test/honeybadger/insights/absinthe_test.exs
+++ b/test/honeybadger/insights/absinthe_test.exs
@@ -29,7 +29,7 @@ defmodule Honeybadger.Insights.AbsintheTest do
       event =
         send_and_receive(
           [:absinthe, :execute, :operation, :stop],
-          %{duration: System.convert_time_unit(25, :millisecond, :native)},
+          %{duration: System.convert_time_unit(25, :microsecond, :native)},
           %{blueprint: blueprint}
         )
 
@@ -64,7 +64,7 @@ defmodule Honeybadger.Insights.AbsintheTest do
       event =
         send_and_receive(
           [:absinthe, :execute, :operation, :exception],
-          %{duration: System.convert_time_unit(15, :millisecond, :native)},
+          %{duration: System.convert_time_unit(15, :microsecond, :native)},
           %{blueprint: blueprint}
         )
 
@@ -95,7 +95,7 @@ defmodule Honeybadger.Insights.AbsintheTest do
       event =
         send_and_receive(
           [:absinthe, :resolve, :field, :stop],
-          %{duration: System.convert_time_unit(5, :millisecond, :native)},
+          %{duration: System.convert_time_unit(5, :microsecond, :native)},
           %{resolution: resolution}
         )
 
@@ -110,7 +110,7 @@ defmodule Honeybadger.Insights.AbsintheTest do
       event =
         send_and_receive(
           [:absinthe, :execute, :operation, :stop],
-          %{duration: System.convert_time_unit(10, :millisecond, :native)},
+          %{duration: System.convert_time_unit(10, :microsecond, :native)},
           # No blueprint data
           %{}
         )
@@ -140,7 +140,7 @@ defmodule Honeybadger.Insights.AbsintheTest do
       event =
         send_and_receive(
           [:absinthe, :execute, :operation, :stop],
-          %{duration: System.convert_time_unit(8, :millisecond, :native)},
+          %{duration: System.convert_time_unit(8, :microsecond, :native)},
           %{blueprint: blueprint}
         )
 
diff --git a/test/honeybadger/insights/base_test.exs b/test/honeybadger/insights/base_test.exs
index 44e77de..fe42f93 100644
--- a/test/honeybadger/insights/base_test.exs
+++ b/test/honeybadger/insights/base_test.exs
@@ -75,14 +75,14 @@ defmodule Honeybadger.Insights.BaseTest do
 
     assert_received {:event_processed, event}, 50
 
-    # Hardcoded expected values after converting native to milliseconds
-    # Assuming 1000 native time units equal 1 millisecond:
-    assert event.duration == 1
-    assert event.total_time == 2
-    assert event.decode_time == 3
-    assert event.query_time == 4
-    assert event.queue_time == 5
-    assert event.idle_time == 6
+    # Hardcoded expected values after converting native to microseconds
+    # Assuming 1000 native time units equal 1 microsecond:
+    assert event[:duration] == 1000
+    assert event[:total_time] == 2000
+    assert event[:decode_time] == 3000
+    assert event[:query_time] == 4000
+    assert event[:queue_time] == 5000
+    assert event[:idle_time] == 6000
 
     refute Map.has_key?(event, :monotonic_time)
 
diff --git a/test/honeybadger/insights/ecto_test.exs b/test/honeybadger/insights/ecto_test.exs
index ac56ce8..54e7963 100644
--- a/test/honeybadger/insights/ecto_test.exs
+++ b/test/honeybadger/insights/ecto_test.exs
@@ -26,9 +26,9 @@ defmodule Honeybadger.Insights.EctoTest do
         send_and_receive(
           [:a, :b, :query],
           %{
-            total_time: System.convert_time_unit(25, :millisecond, :native),
-            decode_time: System.convert_time_unit(5, :millisecond, :native),
-            query_time: System.convert_time_unit(15, :millisecond, :native),
+            total_time: System.convert_time_unit(25, :microsecond, :native),
+            decode_time: System.convert_time_unit(4, :microsecond, :native),
+            query_time: System.convert_time_unit(15, :microsecond, :native),
             queue_time: System.convert_time_unit(5, :millisecond, :native)
           },
           %{
@@ -41,9 +41,9 @@ defmodule Honeybadger.Insights.EctoTest do
       assert event["query"] =~ "SELECT u0.id, u0.name FROM users u0 WHERE u0.id = ?"
       assert event["source"] == "users"
       assert event["total_time"] == 25
-      assert event["decode_time"] == 5
+      assert event["decode_time"] == 4
       assert event["query_time"] == 15
-      assert event["queue_time"] == 5
+      assert event["queue_time"] == 5000
     end
 
     test "ignores excluded sources" do
diff --git a/test/honeybadger/insights/finch_test.exs b/test/honeybadger/insights/finch_test.exs
index cc3520f..5d2b96e 100644
--- a/test/honeybadger/insights/finch_test.exs
+++ b/test/honeybadger/insights/finch_test.exs
@@ -7,7 +7,7 @@ defmodule Honeybadger.Insights.FinchTest do
       event =
         send_and_receive(
           [:finch, :request, :stop],
-          %{duration: System.convert_time_unit(10, :millisecond, :native)},
+          %{duration: System.convert_time_unit(10, :microsecond, :native)},
           %{
             name: :my_client,
             request: %{
@@ -36,7 +36,7 @@ defmodule Honeybadger.Insights.FinchTest do
       event =
         send_and_receive(
           [:finch, :request, :stop],
-          %{duration: System.convert_time_unit(25, :millisecond, :native)},
+          %{duration: System.convert_time_unit(25, :microsecond, :native)},
           %{
             name: :my_client,
             request: %{
@@ -61,7 +61,7 @@ defmodule Honeybadger.Insights.FinchTest do
       event =
         send_and_receive(
           [:finch, :request, :stop],
-          %{duration: System.convert_time_unit(15, :millisecond, :native)},
+          %{duration: System.convert_time_unit(15, :microsecond, :native)},
           %{
             name: :my_client,
             request: %{
@@ -88,7 +88,7 @@ defmodule Honeybadger.Insights.FinchTest do
         event =
           send_and_receive(
             [:finch, :request, :stop],
-            %{duration: System.convert_time_unit(8, :millisecond, :native)},
+            %{duration: System.convert_time_unit(8, :microsecond, :native)},
             %{
               name: :my_client,
               request: %{
@@ -115,7 +115,7 @@ defmodule Honeybadger.Insights.FinchTest do
       event =
         send_and_receive(
           [:finch, :request, :stop],
-          %{duration: System.convert_time_unit(12, :millisecond, :native)},
+          %{duration: System.convert_time_unit(12, :microsecond, :native)},
           %{
             name: :my_client,
             request: %{
@@ -140,7 +140,7 @@ defmodule Honeybadger.Insights.FinchTest do
         event =
           send_and_receive(
             [:finch, :request, :stop],
-            %{duration: System.convert_time_unit(12, :millisecond, :native)},
+            %{duration: System.convert_time_unit(12, :microsecond, :native)},
             %{
               name: :my_client,
               request: %{
diff --git a/test/honeybadger/insights/live_view_test.exs b/test/honeybadger/insights/live_view_test.exs
index b1413bb..3403d06 100644
--- a/test/honeybadger/insights/live_view_test.exs
+++ b/test/honeybadger/insights/live_view_test.exs
@@ -13,7 +13,7 @@ defmodule Honeybadger.Insights.LiveViewTest do
       event =
         send_and_receive(
           [:phoenix, :live_view, :mount, :stop],
-          %{duration: System.convert_time_unit(15, :millisecond, :native)},
+          %{duration: System.convert_time_unit(15, :microsecond, :native)},
           %{
             uri: "/dashboard",
             socket: %{
@@ -40,7 +40,7 @@ defmodule Honeybadger.Insights.LiveViewTest do
       event =
         send_and_receive(
           [:phoenix, :live_view, :mount, :stop],
-          %{duration: System.convert_time_unit(10, :millisecond, :native)},
+          %{duration: System.convert_time_unit(10, :microsecond, :native)},
           %{
             uri: "/dashboard",
             socket_id: "phx-Ghi012",
diff --git a/test/honeybadger/insights/oban_test.exs b/test/honeybadger/insights/oban_test.exs
index 2269853..9a628c9 100644
--- a/test/honeybadger/insights/oban_test.exs
+++ b/test/honeybadger/insights/oban_test.exs
@@ -11,7 +11,7 @@ defmodule Honeybadger.Insights.ObanTest do
       event =
         send_and_receive(
           [:oban, :job, :stop],
-          %{duration: System.convert_time_unit(150, :millisecond, :native)},
+          %{duration: System.convert_time_unit(150, :microsecond, :native)},
           %{
             conf: %{prefix: "oban_jobs"},
             job: %{
@@ -42,7 +42,7 @@ defmodule Honeybadger.Insights.ObanTest do
       event =
         send_and_receive(
           [:oban, :job, :exception],
-          %{duration: System.convert_time_unit(75, :millisecond, :native)},
+          %{duration: System.convert_time_unit(75, :microsecond, :native)},
           %{
             conf: %{prefix: "oban_jobs"},
             job: %{
diff --git a/test/honeybadger/insights/plug_test.exs b/test/honeybadger/insights/plug_test.exs
index b82a57b..5daf709 100644
--- a/test/honeybadger/insights/plug_test.exs
+++ b/test/honeybadger/insights/plug_test.exs
@@ -32,7 +32,7 @@ defmodule Honeybadger.Insights.PlugTest do
       event =
         send_and_receive(
           [:phoenix, :endpoint, :stop],
-          %{duration: System.convert_time_unit(15, :millisecond, :native)},
+          %{duration: System.convert_time_unit(15, :microsecond, :native)},
           %{
             conn:
               mock_conn(%{
@@ -52,7 +52,7 @@ defmodule Honeybadger.Insights.PlugTest do
       event =
         send_and_receive(
           [:phoenix, :endpoint, :stop],
-          %{duration: System.convert_time_unit(10, :millisecond, :native)},
+          %{duration: System.convert_time_unit(10, :microsecond, :native)},
           %{
             conn:
               mock_conn(%{
@@ -77,7 +77,7 @@ defmodule Honeybadger.Insights.PlugTest do
       event =
         send_and_receive(
           [:phoenix, :endpoint, :stop],
-          %{duration: System.convert_time_unit(5, :millisecond, :native)},
+          %{duration: System.convert_time_unit(5, :microsecond, :native)},
           %{
             conn:
               mock_conn(%{
diff --git a/test/honeybadger/insights/tesla_test.exs b/test/honeybadger/insights/tesla_test.exs
index 5298ae3..4e52ba4 100644
--- a/test/honeybadger/insights/tesla_test.exs
+++ b/test/honeybadger/insights/tesla_test.exs
@@ -15,7 +15,7 @@ defmodule Honeybadger.Insights.TeslaTest do
       event =
         send_and_receive(
           [:tesla, :request, :stop],
-          %{duration: System.convert_time_unit(5, :millisecond, :native)},
+          %{duration: System.convert_time_unit(5, :microsecond, :native)},
           %{
             env: %{
               method: :get,
@@ -38,7 +38,7 @@ defmodule Honeybadger.Insights.TeslaTest do
       event =
         send_and_receive(
           [:tesla, :request, :exception],
-          %{duration: System.convert_time_unit(30, :millisecond, :native)},
+          %{duration: System.convert_time_unit(30, :microsecond, :native)},
           %{
             env: %{
               method: :post,
@@ -78,7 +78,7 @@ defmodule Honeybadger.Insights.TeslaTest do
         event =
           send_and_receive(
             [:tesla, :request, :stop],
-            %{duration: System.convert_time_unit(5, :millisecond, :native)},
+            %{duration: System.convert_time_unit(5, :microsecond, :native)},
             %{
               env: %{
                 method: :get,