Add logs about duration of SDK initialization (#23)

* Add logs about duration of SDK initialization

* Move initialization to handle_playing

Author: varsill

lib/agora/agora_dispatcher.ex renamed to lib/agora/dispatcher.ex

@@ -5,6 +5,7 @@ defmodule Membrane.Agora.Sink do
   """
   use Membrane.Sink
 
+  require Membrane.Logger
   require Membrane.Pad, as: Pad
 
   alias Membrane.Agora.Sink.Native
@@ -61,10 +62,26 @@ defmodule Membrane.Agora.Sink do
   end
 
   @impl true
-  def handle_setup(_ctx, state) do
-    {:ok, native_state} =
+  def handle_playing(_ctx, state) do
+    native_state =
       try do
-        Native.create(state.app_id, state.token, state.channel_name, state.user_id)
+        start_time = Membrane.Time.os_time()
+
+        {:ok, native_state} =
+          Native.create(state.app_id, state.token, state.channel_name, state.user_id)
+
+        duration = Membrane.Time.os_time() - start_time
+        duration_ms = Membrane.Time.as_milliseconds(duration, :round)
+        Membrane.Logger.info("Agora SDK initialization took: #{duration_ms} ms")
+
+        if duration_ms > 500 do
+          Membrane.Logger.warning("""
+          Agora SDK initialization took #{duration_ms} ms which is longer than expected.
+          The initial demand made by this sink might be delayed.
+          """)
+        end
+
+        native_state
       rescue
         _e in UndefinedFunctionError ->
           reraise(

lib/agora/agora_sink.ex renamed to lib/agora/sink.ex

@@ -5,6 +5,8 @@ defmodule Membrane.Agora.Source do
   """
   use Membrane.Source
 
+  require Membrane.Logger
+
   alias Membrane.Agora.Source.Native
   alias Membrane.Buffer
 
@@ -62,9 +64,25 @@ defmodule Membrane.Agora.Source do
 
   @impl true
   def handle_playing(_ctx, state) do
-    {:ok, native_state} =
+    native_state =
       try do
-        Native.create(state.app_id, state.token, state.channel_name, state.user_id, self())
+        start_time = Membrane.Time.os_time()
+
+        {:ok, native_state} =
+          Native.create(state.app_id, state.token, state.channel_name, state.user_id, self())
+
+        duration = Membrane.Time.os_time() - start_time
+        duration_ms = Membrane.Time.as_milliseconds(duration, :round)
+        Membrane.Logger.info("Agora SDK initialization took: #{duration_ms} ms")
+
+        if duration_ms > 500 do
+          Membrane.Logger.warning("""
+          Agora SDK initialization took #{duration_ms} ms which is longer than expected.
+          The initial demand made by this sink might be delayed.
+          """)
+        end
+
+        native_state
       rescue
         _e in UndefinedFunctionError ->
           reraise(

lib/agora/agora_sink_native.ex renamed to lib/agora/sink_native.ex

@@ -22,21 +22,23 @@ defmodule Membrane.Agora.IntegrationTest do
         custom_args: [audio: output_audio, video: output_video, framerate: framerate]
       )
 
+    Process.sleep(1_000)
+
     {:ok, _supervisor, sender_pipeline} =
       Membrane.Testing.Pipeline.start_link(
         module: SenderPipeline,
         custom_args: [audio: input_audio, video: input_video, framerate: framerate]
       )
 
-    assert_start_of_stream(receiver_pipeline, :video_sink, :input, 10_000)
+    assert_start_of_stream(receiver_pipeline, :video_sink, :input, 15_000)
     assert_start_of_stream(receiver_pipeline, :audio_sink)
 
     assert_end_of_stream(sender_pipeline, :sink, Pad.ref(:video, _), 30_000)
     assert_end_of_stream(sender_pipeline, :sink, Pad.ref(:audio, _), 30_000)
 
     Membrane.Pipeline.terminate(sender_pipeline)
 
-    assert_end_of_stream(receiver_pipeline, :video_sink, :input, 10_000)
+    assert_end_of_stream(receiver_pipeline, :video_sink, :input, 15_000)
     assert_end_of_stream(receiver_pipeline, :audio_sink)
 
     Membrane.Pipeline.terminate(receiver_pipeline)