Merge pull request #150 from maartenvanvliet/add-batch-telemetry-on-k…

…v-source

Adds batch telemetry event on the KV source

lib/dataloader/kv.ex

@@ -133,7 +133,14 @@ defmodule Dataloader.KV do
 
     def run(source) do
       fun = fn {batch_key, ids} ->
-        {batch_key, source.load_function.(batch_key, ids)}
+        id = :erlang.unique_integer()
+        system_time = System.system_time()
+        start_time_mono = System.monotonic_time()
+
+        emit_start_event(id, system_time, batch_key)
+        batch_result = {batch_key, source.load_function.(batch_key, ids)}
+        emit_stop_event(id, start_time_mono, batch_key)
+        batch_result
       end
 
       results =
@@ -155,5 +162,21 @@ defmodule Dataloader.KV do
     end
 
     def async?(%{opts: opts}), do: opts[:async?]
+
+    defp emit_start_event(id, system_time, batch) do
+      :telemetry.execute(
+        [:dataloader, :source, :batch, :run, :start],
+        %{system_time: system_time},
+        %{id: id, batch: batch}
+      )
+    end
+
+    defp emit_stop_event(id, start_time_mono, batch) do
+      :telemetry.execute(
+        [:dataloader, :source, :batch, :run, :stop],
+        %{duration: System.monotonic_time() - start_time_mono},
+        %{id: id, batch: batch}
+      )
+    end
   end
 end

test/dataloader/ecto_test.exs

@@ -57,7 +57,7 @@ defmodule Dataloader.EctoTest do
 
     :ok =
       :telemetry.attach_many(
-        "#{test}",
+        "#{__MODULE__}_#{test}",
         [
           [:dataloader, :source, :batch, :run, :start],
           [:dataloader, :source, :batch, :run, :stop]

test/dataloader/kv_test.exs

@@ -46,6 +46,44 @@ defmodule Dataloader.KVTest do
     refute_receive(:querying)
   end
 
+  test "basic loading works along with telemetry metrics", %{loader: loader, test: test} do
+    self = self()
+
+    :ok =
+      :telemetry.attach_many(
+        "#{__MODULE__}_#{test}",
+        [
+          [:dataloader, :source, :batch, :run, :start],
+          [:dataloader, :source, :batch, :run, :stop]
+        ],
+        fn name, measurements, metadata, _ ->
+          send(self, {:telemetry_event, name, measurements, metadata})
+        end,
+        nil
+      )
+
+    user_ids = ~w(ben bruce)
+    users = @data[:users]
+
+    loader =
+      loader
+      |> Dataloader.load_many(Test, :users, user_ids)
+      |> Dataloader.run()
+
+    loaded_users =
+      loader
+      |> Dataloader.get_many(Test, :users, user_ids)
+
+    assert length(loaded_users) == 2
+    assert users == loaded_users
+
+    assert_receive {:telemetry_event, [:dataloader, :source, :batch, :run, :start],
+                    %{system_time: _}, %{id: _, batch: _}}
+
+    assert_receive {:telemetry_event, [:dataloader, :source, :batch, :run, :stop], %{duration: _},
+                    %{id: _, batch: _}}
+  end
+
   test "loading something from cache doesn't change the loader", %{loader: loader} do
     round1_loader =
       loader