Skip to content

Commit 262fef5

Browse files
unflxwunflxw
committed
Preserve sub-milli precision in distributions
The Ecto (`ecto_query_time`, `ecto_queue_time`, `ecto_decode_time`, `ecto_idle_time`, `ecto_total_time`) and Oban (`oban_job_duration`, `oban_job_queue_time`) timing distribution metrics were being truncated to whole milliseconds, rounding sub-millisecond measurements down to zero. Report fractional milliseconds instead so fast queries and short job durations are not under-reported. Adds an `Appsignal.Utils.native_to_milliseconds/1` helper for the native -> microsecond -> fractional-millisecond conversion, so the same pattern can be reused elsewhere.
1 parent 7440fb7 commit 262fef5

6 files changed

Lines changed: 60 additions & 44 deletions

File tree

‎.changesets/preserve-sub-millisecond-precision-in-distribution-metrics.md‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
---
2+
bump: patch
3+
type: fix
4+
---
5+
6+
Preserve sub-millisecond precision when reporting timing distribution metrics.
7+
8+
The Ecto (`ecto_query_time`, `ecto_queue_time`, `ecto_decode_time`, `ecto_idle_time`, `ecto_total_time`) and Oban (`oban_job_duration`, `oban_job_queue_time`) distribution metrics now report fractional milliseconds, instead of being truncated to whole milliseconds. Sub-millisecond measurements were previously rounded down to zero.

‎lib/appsignal/ecto.ex‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,7 @@ defmodule Appsignal.Ecto do
44
@tracer Application.compile_env(:appsignal, :appsignal_tracer, Appsignal.Tracer)
55
@span Application.compile_env(:appsignal, :appsignal_span, Appsignal.Span)
66
@appsignal Application.compile_env(:appsignal, :appsignal, Appsignal)
7-
import Appsignal.Utils, only: [module_name: 1]
7+
import Appsignal.Utils, only: [module_name: 1, native_to_milliseconds: 1]
88

99
# For each measurement Ecto emits, the tag combinations we want to fan out to.
1010
# `:hostname` -> tagged by repo + hostname (BEAM-side dimension).
@@ -95,7 +95,7 @@ defmodule Appsignal.Ecto do
9595
value = Map.get(measurements, key)
9696

9797
if is_integer(value) do
98-
ms = System.convert_time_unit(value, :native, :millisecond)
98+
ms = native_to_milliseconds(value)
9999
metric = "ecto_#{key}"
100100

101101
if :hostname in modes do

‎lib/appsignal/oban.ex‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,8 @@ defmodule Appsignal.Oban do
55
@span Application.compile_env(:appsignal, :appsignal_span, Appsignal.Span)
66
@appsignal Application.compile_env(:appsignal, :appsignal, Appsignal)
77

8+
import Appsignal.Utils, only: [native_to_milliseconds: 1]
9+
810
@moduledoc false
911

1012
def attach do
@@ -232,14 +234,14 @@ defmodule Appsignal.Oban do
232234
Enum.each(tag_combinations, fn tags ->
233235
@appsignal.add_distribution_value(
234236
"oban_job_duration",
235-
System.convert_time_unit(duration, :native, :millisecond),
237+
native_to_milliseconds(duration),
236238
tags
237239
)
238240
end)
239241
end
240242

241243
defp add_job_queue_time_value(job, queue) do
242-
delay = DateTime.diff(job.attempted_at, job.scheduled_at, :millisecond)
244+
delay = DateTime.diff(job.attempted_at, job.scheduled_at, :microsecond) / 1000
243245

244246
@appsignal.add_distribution_value("oban_job_queue_time", delay, %{
245247
queue: to_string(queue)

‎lib/appsignal/utils.ex‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,22 @@ defmodule Appsignal.Utils do
1919

2020
def module_name(module), do: module |> to_string() |> module_name()
2121

22+
@doc """
23+
Converts a native-unit duration to fractional milliseconds, preserving
24+
sub-millisecond precision. Use this when reporting timings as distribution
25+
metric values.
26+
27+
## Examples
28+
29+
iex> Appsignal.Utils.native_to_milliseconds(System.convert_time_unit(1500, :microsecond, :native))
30+
1.5
31+
32+
"""
33+
@spec native_to_milliseconds(integer()) :: float()
34+
def native_to_milliseconds(native) when is_integer(native) do
35+
System.convert_time_unit(native, :native, :microsecond) / 1000
36+
end
37+
2238
def info(message) do
2339
require Logger
2440
Logger.info(message)

‎test/appsignal/ecto_test.exs‎

Lines changed: 10 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -82,7 +82,7 @@ defmodule Appsignal.EctoTest do
8282
decode_time: 2_204_000,
8383
query_time: 5_386_000,
8484
queue_time: 1_239_000,
85-
idle_time: 12_000_000,
85+
idle_time: 12_017_000,
8686
total_time: 8_829_000
8787
},
8888
%{
@@ -100,58 +100,48 @@ defmodule Appsignal.EctoTest do
100100
end
101101

102102
test "adds query_time with both hostname and source tags", %{fake_appsignal: f} do
103-
expected = System.convert_time_unit(5_386_000, :native, :millisecond)
104-
105103
assert [
106-
%{value: ^expected, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
104+
%{value: 5.386, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
107105
%{
108-
value: ^expected,
106+
value: 5.386,
109107
tags: %{repo: "Appsignal.Test.Repo", hostname: "Bobs-MBP.example.com"}
110108
}
111109
] = FakeAppsignal.get_distribution_values(f, "ecto_query_time")
112110
end
113111

114112
test "adds decode_time with both hostname and source tags", %{fake_appsignal: f} do
115-
expected = System.convert_time_unit(2_204_000, :native, :millisecond)
116-
117113
assert [
118-
%{value: ^expected, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
114+
%{value: 2.204, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
119115
%{
120-
value: ^expected,
116+
value: 2.204,
121117
tags: %{repo: "Appsignal.Test.Repo", hostname: "Bobs-MBP.example.com"}
122118
}
123119
] = FakeAppsignal.get_distribution_values(f, "ecto_decode_time")
124120
end
125121

126122
test "adds total_time with both hostname and source tags", %{fake_appsignal: f} do
127-
expected = System.convert_time_unit(8_829_000, :native, :millisecond)
128-
129123
assert [
130-
%{value: ^expected, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
124+
%{value: 8.829, tags: %{repo: "Appsignal.Test.Repo", source: "users"}},
131125
%{
132-
value: ^expected,
126+
value: 8.829,
133127
tags: %{repo: "Appsignal.Test.Repo", hostname: "Bobs-MBP.example.com"}
134128
}
135129
] = FakeAppsignal.get_distribution_values(f, "ecto_total_time")
136130
end
137131

138132
test "adds queue_time with hostname tags only", %{fake_appsignal: f} do
139-
expected = System.convert_time_unit(1_239_000, :native, :millisecond)
140-
141133
assert [
142134
%{
143-
value: ^expected,
135+
value: 1.239,
144136
tags: %{repo: "Appsignal.Test.Repo", hostname: "Bobs-MBP.example.com"}
145137
}
146138
] = FakeAppsignal.get_distribution_values(f, "ecto_queue_time")
147139
end
148140

149141
test "adds idle_time with hostname tags only", %{fake_appsignal: f} do
150-
expected = System.convert_time_unit(12_000_000, :native, :millisecond)
151-
152142
assert [
153143
%{
154-
value: ^expected,
144+
value: 12.017,
155145
tags: %{repo: "Appsignal.Test.Repo", hostname: "Bobs-MBP.example.com"}
156146
}
157147
] = FakeAppsignal.get_distribution_values(f, "ecto_idle_time")
@@ -172,7 +162,7 @@ defmodule Appsignal.EctoTest do
172162
decode_time: 2_204_000,
173163
query_time: 5_386_000,
174164
queue_time: 1_239_000,
175-
idle_time: 12_000_000,
165+
idle_time: 12_017_000,
176166
total_time: 8_829_000
177167
},
178168
%{

‎test/appsignal/oban_test.exs‎

Lines changed: 20 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -118,7 +118,7 @@ defmodule Appsignal.ObanTest do
118118

119119
test "adds job queue time distribution value", %{fake_appsignal: fake_appsignal} do
120120
assert [
121-
%{key: _, value: 3000, tags: %{queue: "default"}}
121+
%{key: _, value: 3456.789, tags: %{queue: "default"}}
122122
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_queue_time")
123123
end
124124
end
@@ -176,13 +176,13 @@ defmodule Appsignal.ObanTest do
176176

177177
test "adds job duration distribution value", %{fake_appsignal: fake_appsignal} do
178178
assert [
179-
%{key: _, value: 123, tags: %{worker: "Test.Worker"}},
179+
%{key: _, value: 123.456, tags: %{worker: "Test.Worker"}},
180180
%{
181181
key: _,
182-
value: 123,
182+
value: 123.456,
183183
tags: %{hostname: "Bobs-MBP.example.com", worker: "Test.Worker"}
184184
},
185-
%{key: _, value: 123, tags: %{state: "success", worker: "Test.Worker"}}
185+
%{key: _, value: 123.456, tags: %{state: "success", worker: "Test.Worker"}}
186186
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_duration")
187187
end
188188

@@ -223,13 +223,13 @@ defmodule Appsignal.ObanTest do
223223

224224
test "adds job duration distribution value", %{fake_appsignal: fake_appsignal} do
225225
assert [
226-
%{key: _, value: 123, tags: %{worker: "Test.Worker"}},
226+
%{key: _, value: 123.456, tags: %{worker: "Test.Worker"}},
227227
%{
228228
key: _,
229-
value: 123,
229+
value: 123.456,
230230
tags: %{hostname: "Bobs-MBP.example.com", worker: "Test.Worker"}
231231
},
232-
%{key: _, value: 123, tags: %{state: "snoozed", worker: "Test.Worker"}}
232+
%{key: _, value: 123.456, tags: %{state: "snoozed", worker: "Test.Worker"}}
233233
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_duration")
234234
end
235235
end
@@ -317,13 +317,13 @@ defmodule Appsignal.ObanTest do
317317

318318
test "adds job duration distribution value", %{fake_appsignal: fake_appsignal} do
319319
assert [
320-
%{key: _, value: 123, tags: %{worker: "Test.Worker"}},
320+
%{key: _, value: 123.456, tags: %{worker: "Test.Worker"}},
321321
%{
322322
key: _,
323-
value: 123,
323+
value: 123.456,
324324
tags: %{hostname: "Bobs-MBP.example.com", worker: "Test.Worker"}
325325
},
326-
%{key: _, value: 123, tags: %{state: "failure", worker: "Test.Worker"}}
326+
%{key: _, value: 123.456, tags: %{state: "failure", worker: "Test.Worker"}}
327327
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_duration")
328328
end
329329

@@ -401,13 +401,13 @@ defmodule Appsignal.ObanTest do
401401

402402
test "adds job duration distribution value", %{fake_appsignal: fake_appsignal} do
403403
assert [
404-
%{key: _, value: 123, tags: %{worker: "Test.Worker"}},
404+
%{key: _, value: 123.456, tags: %{worker: "Test.Worker"}},
405405
%{
406406
key: _,
407-
value: 123,
407+
value: 123.456,
408408
tags: %{hostname: "Bobs-MBP.example.com", worker: "Test.Worker"}
409409
},
410-
%{key: _, value: 123, tags: %{state: "failure", worker: "Test.Worker"}}
410+
%{key: _, value: 123.456, tags: %{state: "failure", worker: "Test.Worker"}}
411411
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_duration")
412412
end
413413

@@ -450,13 +450,13 @@ defmodule Appsignal.ObanTest do
450450

451451
test "adds job duration distribution value", %{fake_appsignal: fake_appsignal} do
452452
assert [
453-
%{key: _, value: 123, tags: %{worker: "Test.Worker"}},
453+
%{key: _, value: 123.456, tags: %{worker: "Test.Worker"}},
454454
%{
455455
key: _,
456-
value: 123,
456+
value: 123.456,
457457
tags: %{hostname: "Bobs-MBP.example.com", worker: "Test.Worker"}
458458
},
459-
%{key: _, value: 123, tags: %{state: "discard", worker: "Test.Worker"}}
459+
%{key: _, value: 123.456, tags: %{state: "discard", worker: "Test.Worker"}}
460460
] = FakeAppsignal.get_distribution_values(fake_appsignal, "oban_job_duration")
461461
end
462462
end
@@ -737,7 +737,7 @@ defmodule Appsignal.ObanTest do
737737
defp execute_job_stop(additional_metadata \\ %{}) do
738738
:telemetry.execute(
739739
[:oban, :job, :stop],
740-
%{duration: 123 * 1_000_000},
740+
%{duration: 123_456_000},
741741
Map.merge(sample_metadata(), additional_metadata)
742742
)
743743
end
@@ -756,7 +756,7 @@ defmodule Appsignal.ObanTest do
756756

757757
:telemetry.execute(
758758
[:oban, :job, :exception],
759-
%{duration: 123 * 1_000_000},
759+
%{duration: 123_456_000},
760760
Map.merge(metadata, additional_metadata)
761761
)
762762
end
@@ -785,8 +785,8 @@ defmodule Appsignal.ObanTest do
785785
defp sample_job do
786786
%{
787787
priority: 0,
788-
scheduled_at: DateTime.from_unix!(1_234_000_000),
789-
attempted_at: DateTime.from_unix!(1_234_000_003),
788+
scheduled_at: DateTime.from_unix!(1_234_000_000_000_000, :microsecond),
789+
attempted_at: DateTime.from_unix!(1_234_000_003_456_789, :microsecond),
790790
meta: %{
791791
number: 123,
792792
string: "foo",

0 commit comments

Comments
 (0)