diff --git a/assets/css/tooltips.css b/assets/css/tooltips.css index 5957b6ef9..6ad850e8f 100644 --- a/assets/css/tooltips.css +++ b/assets/css/tooltips.css @@ -21,6 +21,10 @@ Example usage: --distance: 28px; } +.tooltip.distant-medium { + --distance: 10px; +} + /* Tooltip text */ .tooltip:before { position: absolute; diff --git a/lib/livebook/evaluator.ex b/lib/livebook/evaluator.ex index adbc5601d..1a881aa60 100644 --- a/lib/livebook/evaluator.ex +++ b/lib/livebook/evaluator.ex @@ -67,7 +67,7 @@ defmodule Livebook.Evaluator do Any subsequent calls may specify `prev_ref` pointing to a previous evaluation, in which case the corresponding binding and environment are used during evaluation. - Evaluation response is sent to the process identified by `send_to` as `{:evaluation_response, ref, response}`. + Evaluation response is sent to the process identified by `send_to` as `{:evaluation_response, ref, response, metadata}`. Note that response is transformed with the configured formatter (identity by default). ## Options @@ -137,6 +137,7 @@ defmodule Livebook.Evaluator do context = Map.get_lazy(state.contexts, prev_ref, fn -> initial_context() end) file = Keyword.get(opts, :file, "nofile") context = put_in(context.env.file, file) + start_time = System.monotonic_time() {result_context, response} = case eval(code, context.binding, context.env) do @@ -150,13 +151,16 @@ defmodule Livebook.Evaluator do {context, response} end + evaluation_time_ms = get_execution_time_delta(start_time) + state = put_in(state.contexts[ref], result_context) Evaluator.IOProxy.flush(state.io_proxy) Evaluator.IOProxy.clear_input_buffers(state.io_proxy) output = state.formatter.format_response(response) - send(send_to, {:evaluation_response, ref, output}) + metadata = %{evaluation_time_ms: evaluation_time_ms} + send(send_to, {:evaluation_response, ref, output, metadata}) widget_pids = Evaluator.IOProxy.flush_widgets(state.io_proxy) state = track_evaluation_widgets(state, ref, widget_pids, output) @@ -271,4 +275,10 @@ defmodule Livebook.Evaluator do end def widget_pid_from_output(_output), do: :error + + defp get_execution_time_delta(started_at) do + System.monotonic_time() + |> Kernel.-(started_at) + |> System.convert_time_unit(:native, :millisecond) + end end diff --git a/lib/livebook/runtime.ex b/lib/livebook/runtime.ex index f7380b7c5..95061142e 100644 --- a/lib/livebook/runtime.ex +++ b/lib/livebook/runtime.ex @@ -53,7 +53,7 @@ defprotocol Livebook.Runtime do The messages should be of the form: * `{:evaluation_output, ref, output}` - output captured during evaluation - * `{:evaluation_response, ref, output}` - final result of the evaluation + * `{:evaluation_response, ref, output, metadata}` - final result of the evaluation, recognised metadata entries are: `evaluation_time_ms` The evaluation may request user input by sending `{:evaluation_input, ref, reply_to, prompt}` to the runtime owner, who is supposed to reply with `{:evaluation_input_reply, reply}` diff --git a/lib/livebook/session.ex b/lib/livebook/session.ex index 57554c60c..3d22cf49c 100644 --- a/lib/livebook/session.ex +++ b/lib/livebook/session.ex @@ -489,8 +489,8 @@ defmodule Livebook.Session do {:noreply, handle_operation(state, operation)} end - def handle_info({:evaluation_response, cell_id, response}, state) do - operation = {:add_cell_evaluation_response, self(), cell_id, response} + def handle_info({:evaluation_response, cell_id, response, metadata}, state) do + operation = {:add_cell_evaluation_response, self(), cell_id, response, metadata} {:noreply, handle_operation(state, operation)} end diff --git a/lib/livebook/session/data.ex b/lib/livebook/session/data.ex index 9f42c0cee..f049899a5 100644 --- a/lib/livebook/session/data.ex +++ b/lib/livebook/session/data.ex @@ -55,7 +55,8 @@ defmodule Livebook.Session.Data do revision: cell_revision(), deltas: list(Delta.t()), revision_by_client_pid: %{pid() => cell_revision()}, - evaluation_digest: String.t() | nil + evaluation_digest: String.t() | nil, + evaluation_time_ms: integer() | nil } @type cell_revision :: non_neg_integer() @@ -291,13 +292,13 @@ defmodule Livebook.Session.Data do end end - def apply_operation(data, {:add_cell_evaluation_response, _client_pid, id, output}) do + def apply_operation(data, {:add_cell_evaluation_response, _client_pid, id, output, metadata}) do with {:ok, cell, section} <- Notebook.fetch_cell_and_section(data.notebook, id), :evaluating <- data.cell_infos[cell.id].evaluation_status do data |> with_actions() |> add_cell_evaluation_response(cell, output) - |> finish_cell_evaluation(cell, section) + |> finish_cell_evaluation(cell, section, metadata) |> mark_dependent_cells_as_stale(cell) |> maybe_evaluate_queued() |> wrap_ok() @@ -549,7 +550,9 @@ defmodule Livebook.Session.Data do |> update_section_info!(section.id, fn section -> %{section | evaluation_queue: section.evaluation_queue ++ [cell.id]} end) - |> set_cell_info!(cell.id, evaluation_status: :queued) + |> set_cell_info!(cell.id, + evaluation_status: :queued + ) end defp unqueue_cell_evaluation(data_actions, cell, section) do @@ -600,11 +603,12 @@ defmodule Livebook.Session.Data do |> Enum.join("\n") end - defp finish_cell_evaluation(data_actions, cell, section) do + defp finish_cell_evaluation(data_actions, cell, section, metadata) do data_actions |> set_cell_info!(cell.id, validity_status: :evaluated, - evaluation_status: :ready + evaluation_status: :ready, + evaluation_time_ms: metadata.evaluation_time_ms ) |> set_section_info!(section.id, evaluating_cell_id: nil) end @@ -877,7 +881,8 @@ defmodule Livebook.Session.Data do revision_by_client_pid: Map.new(client_pids, &{&1, 0}), validity_status: :fresh, evaluation_status: :ready, - evaluation_digest: nil + evaluation_digest: nil, + evaluation_time_ms: nil } end diff --git a/lib/livebook_web/live/session_live.ex b/lib/livebook_web/live/session_live.ex index 216e0b729..ed7c17a50 100644 --- a/lib/livebook_web/live/session_live.ex +++ b/lib/livebook_web/live/session_live.ex @@ -850,7 +850,8 @@ defmodule LivebookWeb.SessionLive do empty?: cell.source == "", outputs: cell.outputs, validity_status: info.validity_status, - evaluation_status: info.evaluation_status + evaluation_status: info.evaluation_status, + evaluation_time_ms: info.evaluation_time_ms } end diff --git a/lib/livebook_web/live/session_live/cell_component.ex b/lib/livebook_web/live/session_live/cell_component.ex index 034eac3b5..454226688 100644 --- a/lib/livebook_web/live/session_live/cell_component.ex +++ b/lib/livebook_web/live/session_live/cell_component.ex @@ -224,7 +224,7 @@ defmodule LivebookWeb.SessionLive.CellComponent do <%= if @cell_view.type == :elixir do %>
- <%= render_cell_status(@cell_view.validity_status, @cell_view.evaluation_status) %> + <%= render_cell_status(@cell_view.validity_status, @cell_view.evaluation_status, @cell_view.evaluation_time_ms) %>
<% end %> @@ -350,56 +350,76 @@ defmodule LivebookWeb.SessionLive.CellComponent do """ end - defp render_cell_status(validity_status, evaluation_status) + defp render_cell_status(cell_view, evaluation_status, evaluation_time_ms) - defp render_cell_status(_, :evaluating) do + defp render_cell_status(_, :evaluating, _) do render_status_indicator("Evaluating", "bg-blue-500", animated_circle_class: "bg-blue-400", change_indicator: true ) end - defp render_cell_status(_, :queued) do + defp render_cell_status(_, :queued, _) do render_status_indicator("Queued", "bg-gray-500", animated_circle_class: "bg-gray-400") end - defp render_cell_status(:evaluated, _) do - render_status_indicator("Evaluated", "bg-green-400", change_indicator: true) + defp render_cell_status(:evaluated, _, evaluation_time_ms) do + render_status_indicator("Evaluated", "bg-green-400", + change_indicator: true, + tooltip: evaluated_label(evaluation_time_ms) + ) end - defp render_cell_status(:stale, _) do + defp render_cell_status(:stale, _, _) do render_status_indicator("Stale", "bg-yellow-200", change_indicator: true) end - defp render_cell_status(:aborted, _) do + defp render_cell_status(:aborted, _, _) do render_status_indicator("Aborted", "bg-red-400") end - defp render_cell_status(_, _), do: nil + defp render_cell_status(_, _, _), do: nil defp render_status_indicator(text, circle_class, opts \\ []) do assigns = %{ text: text, circle_class: circle_class, animated_circle_class: Keyword.get(opts, :animated_circle_class), - change_indicator: Keyword.get(opts, :change_indicator, false) + change_indicator: Keyword.get(opts, :change_indicator, false), + tooltip: Keyword.get(opts, :tooltip) } ~L""" -
-
- <%= @text %> - <%= if @change_indicator do %> - * - <% end %> +
bottom distant-medium" aria-label="<%= @tooltip %>"> +
+
+ <%= @text %> + <%= if @change_indicator do %> + * + <% end %> +
+ + <%= if @animated_circle_class do %> + + <% end %> + +
- - <%= if @animated_circle_class do %> - - <% end %> - -
""" end + + defp evaluated_label(time_ms) when is_integer(time_ms) do + evaluation_time = + if time_ms > 100 do + seconds = time_ms |> Kernel./(1000) |> Float.floor(1) + "#{seconds}s" + else + "#{time_ms}ms" + end + + "Took " <> evaluation_time + end + + defp evaluated_label(_time_ms), do: nil end diff --git a/test/livebook/evaluator_test.exs b/test/livebook/evaluator_test.exs index a96eefcd3..5ea9f5221 100644 --- a/test/livebook/evaluator_test.exs +++ b/test/livebook/evaluator_test.exs @@ -18,35 +18,35 @@ defmodule Livebook.EvaluatorTest do Evaluator.evaluate_code(evaluator, self(), code, :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, 3}} + assert_receive {:evaluation_response, :code_1, {:ok, 3}, %{evaluation_time_ms: _time_ms}} end test "given no prev_ref does not see previous evaluation context", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), "x = 1", :code_1) - assert_receive {:evaluation_response, :code_1, _} + assert_receive {:evaluation_response, :code_1, _, %{evaluation_time_ms: _time_ms}} ignore_warnings(fn -> Evaluator.evaluate_code(evaluator, self(), "x", :code_2) assert_receive {:evaluation_response, :code_2, {:error, _kind, %CompileError{description: "undefined function x/0"}, - _stacktrace}} + _stacktrace}, %{evaluation_time_ms: _time_ms}} end) end test "given prev_ref sees previous evaluation context", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), "x = 1", :code_1) - assert_receive {:evaluation_response, :code_1, _} + assert_receive {:evaluation_response, :code_1, _, %{evaluation_time_ms: _time_ms}} Evaluator.evaluate_code(evaluator, self(), "x", :code_2, :code_1) - assert_receive {:evaluation_response, :code_2, {:ok, 1}} + assert_receive {:evaluation_response, :code_2, {:ok, 1}, %{evaluation_time_ms: _time_ms}} end test "given invalid prev_ref just uses default context", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), ":hey", :code_1, :code_nonexistent) - assert_receive {:evaluation_response, :code_1, {:ok, :hey}} + assert_receive {:evaluation_response, :code_1, {:ok, :hey}, %{evaluation_time_ms: _time_ms}} end test "captures standard output and sends it to the caller", %{evaluator: evaluator} do @@ -61,7 +61,8 @@ defmodule Livebook.EvaluatorTest do assert_receive {:evaluation_input, :code_1, reply_to, "name: "} send(reply_to, {:evaluation_input_reply, {:ok, "Jake Peralta\n"}}) - assert_receive {:evaluation_response, :code_1, {:ok, "Jake Peralta\n"}} + assert_receive {:evaluation_response, :code_1, {:ok, "Jake Peralta\n"}, + %{evaluation_time_ms: _time_ms}} end test "returns error along with its kind and stacktrace", %{evaluator: evaluator} do @@ -73,7 +74,7 @@ defmodule Livebook.EvaluatorTest do assert_receive {:evaluation_response, :code_1, {:error, :error, %FunctionClauseError{}, - [{List, :first, _arity, _location}]}} + [{List, :first, _arity, _location}]}, %{evaluation_time_ms: _time_ms}} end test "in case of an error returns only the relevant part of stacktrace", %{ @@ -107,7 +108,8 @@ defmodule Livebook.EvaluatorTest do # Note: evaluating module definitions is relatively slow, so we use a higher wait timeout. assert_receive {:evaluation_response, :code_1, - {:error, _kind, _error, ^expected_stacktrace}}, + {:error, _kind, _error, ^expected_stacktrace}, + %{evaluation_time_ms: _time_ms}}, 1_000 end) end @@ -127,13 +129,15 @@ defmodule Livebook.EvaluatorTest do """ Evaluator.evaluate_code(evaluator, self(), code1, :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, _}} + assert_receive {:evaluation_response, :code_1, {:ok, _}, %{evaluation_time_ms: _time_ms}} Evaluator.evaluate_code(evaluator, self(), code2, :code_2, :code_1) - assert_receive {:evaluation_response, :code_2, {:error, _, _, _}} + + assert_receive {:evaluation_response, :code_2, {:error, _, _, _}, + %{evaluation_time_ms: _time_ms}} Evaluator.evaluate_code(evaluator, self(), code3, :code_3, :code_2) - assert_receive {:evaluation_response, :code_3, {:ok, 4}} + assert_receive {:evaluation_response, :code_3, {:ok, 4}, %{evaluation_time_ms: _time_ms}} end test "given file option sets it in evaluation environment", %{evaluator: evaluator} do @@ -144,7 +148,8 @@ defmodule Livebook.EvaluatorTest do opts = [file: "/path/dir/file"] Evaluator.evaluate_code(evaluator, self(), code, :code_1, nil, opts) - assert_receive {:evaluation_response, :code_1, {:ok, "/path/dir"}} + assert_receive {:evaluation_response, :code_1, {:ok, "/path/dir"}, + %{evaluation_time_ms: _time_ms}} end test "kills widgets that that no evaluation points to", %{evaluator: evaluator} do @@ -152,10 +157,14 @@ defmodule Livebook.EvaluatorTest do # First of them should be eventually killed Evaluator.evaluate_code(evaluator, self(), spawn_widget_code(), :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}} + + assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}, + %{evaluation_time_ms: _time_ms}} Evaluator.evaluate_code(evaluator, self(), spawn_widget_code(), :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, widget_pid2}} + + assert_receive {:evaluation_response, :code_1, {:ok, widget_pid2}, + %{evaluation_time_ms: _time_ms}} ref = Process.monitor(widget_pid1) assert_receive {:DOWN, ^ref, :process, ^widget_pid1, :shutdown} @@ -165,10 +174,14 @@ defmodule Livebook.EvaluatorTest do test "does not kill a widget if another evaluation points to it", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), spawn_widget_code(), :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}} + + assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}, + %{evaluation_time_ms: _time_ms}} Evaluator.evaluate_code(evaluator, self(), spawn_widget_code(), :code_2) - assert_receive {:evaluation_response, :code_2, {:ok, widget_pid2}} + + assert_receive {:evaluation_response, :code_2, {:ok, widget_pid2}, + %{evaluation_time_ms: _time_ms}} ref = Process.monitor(widget_pid1) refute_receive {:DOWN, ^ref, :process, ^widget_pid1, :shutdown} @@ -181,7 +194,7 @@ defmodule Livebook.EvaluatorTest do describe "forget_evaluation/2" do test "invalidates the given reference", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), "x = 1", :code_1) - assert_receive {:evaluation_response, :code_1, _} + assert_receive {:evaluation_response, :code_1, _, %{evaluation_time_ms: _time_ms}} Evaluator.forget_evaluation(evaluator, :code_1) @@ -190,13 +203,15 @@ defmodule Livebook.EvaluatorTest do assert_receive {:evaluation_response, :code_2, {:error, _kind, %CompileError{description: "undefined function x/0"}, - _stacktrace}} + _stacktrace}, %{evaluation_time_ms: _time_ms}} end) end test "kills widgets that no evaluation points to", %{evaluator: evaluator} do Evaluator.evaluate_code(evaluator, self(), spawn_widget_code(), :code_1) - assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}} + + assert_receive {:evaluation_response, :code_1, {:ok, widget_pid1}, + %{evaluation_time_ms: _time_ms}} Evaluator.forget_evaluation(evaluator, :code_1) @@ -218,7 +233,7 @@ defmodule Livebook.EvaluatorTest do """ Evaluator.evaluate_code(evaluator, self(), code, :code_1) - assert_receive {:evaluation_response, :code_1, _} + assert_receive {:evaluation_response, :code_1, _, %{evaluation_time_ms: _time_ms}} Evaluator.request_completion_items(evaluator, self(), :comp_ref, "num", :code_1) assert_receive {:completion_response, :comp_ref, [%{label: "number"}]}, 1_000 diff --git a/test/livebook/runtime/erl_dist/manager_test.exs b/test/livebook/runtime/erl_dist/manager_test.exs index b055463a7..11a021a5c 100644 --- a/test/livebook/runtime/erl_dist/manager_test.exs +++ b/test/livebook/runtime/erl_dist/manager_test.exs @@ -34,7 +34,7 @@ defmodule Livebook.Runtime.ErlDist.ManagerTest do Manager.set_owner(node(), self()) Manager.evaluate_code(node(), "1 + 1", :container1, :evaluation1, nil) - assert_receive {:evaluation_response, :evaluation1, _} + assert_receive {:evaluation_response, :evaluation1, _, %{evaluation_time_ms: _time_ms}} Manager.stop(node()) end @@ -48,8 +48,8 @@ defmodule Livebook.Runtime.ErlDist.ManagerTest do Manager.evaluate_code(node(), "defmodule Foo do end", :container1, :evaluation1, nil) Manager.evaluate_code(node(), "defmodule Foo do end", :container1, :evaluation2, nil) - assert_receive {:evaluation_response, :evaluation1, _} - assert_receive {:evaluation_response, :evaluation2, _} + assert_receive {:evaluation_response, :evaluation1, _, %{evaluation_time_ms: _time_ms}} + assert_receive {:evaluation_response, :evaluation2, _, %{evaluation_time_ms: _time_ms}} end) assert stderr == "" @@ -103,9 +103,10 @@ defmodule Livebook.Runtime.ErlDist.ManagerTest do Manager.set_owner(node(), self()) Manager.evaluate_code(node(), "number = 10", :c1, :e1, nil) - assert_receive {:evaluation_response, :e1, _} + assert_receive {:evaluation_response, :e1, _, %{evaluation_time_ms: _time_ms}} Manager.request_completion_items(node(), self(), :comp_ref, "num", :c1, :e1) + assert_receive {:completion_response, :comp_ref, [%{label: "number"}]} Manager.stop(node()) diff --git a/test/livebook/session/data_test.exs b/test/livebook/session/data_test.exs index 627b8035b..1169bd388 100644 --- a/test/livebook/session/data_test.exs +++ b/test/livebook/session/data_test.exs @@ -191,9 +191,11 @@ defmodule Livebook.Session.DataTest do # Evaluate both cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 20}} ]) operation = {:delete_cell, self(), "c1"} @@ -248,13 +250,13 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 30}}, {:queue_cell_evaluation, self(), "c4"}, - {:add_cell_evaluation_response, self(), "c4", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c4", {:ok, nil}, %{evaluation_time_ms: 40}} ]) operation = {:move_cell, self(), "c3", -1} @@ -289,13 +291,13 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 30}}, {:queue_cell_evaluation, self(), "c4"}, - {:add_cell_evaluation_response, self(), "c4", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c4", {:ok, nil}, %{evaluation_time_ms: 40}} ]) operation = {:move_cell, self(), "c2", 1} @@ -354,11 +356,11 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 30}} ]) operation = {:move_cell, self(), "c1", 1} @@ -379,7 +381,7 @@ defmodule Livebook.Session.DataTest do # Evaluate the Elixir cell {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}} ]) operation = {:move_cell, self(), "c2", -1} @@ -426,9 +428,9 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 20}} ]) operation = {:move_cell, self(), "c1", 1} @@ -474,13 +476,13 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 30}}, {:queue_cell_evaluation, self(), "c4"}, - {:add_cell_evaluation_response, self(), "c4", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c4", {:ok, nil}, %{evaluation_time_ms: 40}} ]) operation = {:move_section, self(), "s2", -1} @@ -519,13 +521,13 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 100}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c4"}, - {:add_cell_evaluation_response, self(), "c4", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c4", {:ok, nil}, %{evaluation_time_ms: 0}} ]) operation = {:move_section, self(), "s1", 1} @@ -564,11 +566,11 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, nil}, %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 30}} ]) operation = {:move_section, self(), "s1", 1} @@ -590,7 +592,7 @@ defmodule Livebook.Session.DataTest do # Evaluate the Elixir cell {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}} ]) operation = {:move_section, self(), "s2", -1} @@ -642,9 +644,9 @@ defmodule Livebook.Session.DataTest do # Evaluate cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, nil}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, nil}, %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, nil}} + {:add_cell_evaluation_response, self(), "c3", {:ok, nil}, %{evaluation_time_ms: 20}} ]) operation = {:move_section, self(), "s4", -1} @@ -814,12 +816,15 @@ defmodule Livebook.Session.DataTest do # Evaluate first 2 cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 20}}, # Evaluate the first cell, so the second becomes stale {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 30}} ]) # The above leads to: @@ -954,7 +959,8 @@ defmodule Livebook.Session.DataTest do {:insert_cell, self(), "s1", 0, :elixir, "c1"}, {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}} ]) operation = {:add_cell_evaluation_output, self(), "c1", "Hello!"} @@ -982,7 +988,8 @@ defmodule Livebook.Session.DataTest do {:queue_cell_evaluation, self(), "c1"} ]) - operation = {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} assert {:ok, %{ @@ -1006,7 +1013,8 @@ defmodule Livebook.Session.DataTest do {:queue_cell_evaluation, self(), "c1"} ]) - operation = {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} assert {:ok, %{ @@ -1026,7 +1034,8 @@ defmodule Livebook.Session.DataTest do {:queue_cell_evaluation, self(), "c2"} ]) - operation = {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} assert {:ok, %{ @@ -1049,7 +1058,8 @@ defmodule Livebook.Session.DataTest do {:queue_cell_evaluation, self(), "c2"} ]) - operation = {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} assert {:ok, %{ @@ -1097,16 +1107,20 @@ defmodule Livebook.Session.DataTest do # Evaluate all cells {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 20}}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c3", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c3", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 30}}, # Queue the first cell again {:queue_cell_evaluation, self(), "c1"} ]) - operation = {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} assert {:ok, %{ @@ -1116,6 +1130,28 @@ defmodule Livebook.Session.DataTest do } }, []} = Data.apply_operation(data, operation) end + + test "adds evaluation time to the response" do + data = + data_after_operations!([ + {:insert_section, self(), 0, "s1"}, + {:insert_cell, self(), "s1", 0, :elixir, "c1"}, + {:set_runtime, self(), NoopRuntime.new()}, + {:queue_cell_evaluation, self(), "c1"} + ]) + + operation = + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, %{evaluation_time_ms: 10}} + + Process.sleep(10) + + assert {:ok, + %{ + cell_infos: %{"c1" => %{evaluation_time_ms: evaluation_time}} + }, []} = Data.apply_operation(data, operation) + + assert evaluation_time >= 10 + end end describe "apply_operation/2 given :reflect_evaluation_failure" do @@ -1130,7 +1166,8 @@ defmodule Livebook.Session.DataTest do {:queue_cell_evaluation, self(), "c1"}, {:queue_cell_evaluation, self(), "c2"}, {:queue_cell_evaluation, self(), "c3"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}} ]) operation = {:reflect_evaluation_failure, self()} @@ -1163,7 +1200,8 @@ defmodule Livebook.Session.DataTest do {:insert_cell, self(), "s1", 0, :elixir, "c1"}, {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}} ]) operation = {:cancel_cell_evaluation, self(), "c1"} @@ -1180,7 +1218,8 @@ defmodule Livebook.Session.DataTest do {:insert_cell, self(), "s2", 0, :elixir, "c3"}, {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c1"}, - {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}}, + {:add_cell_evaluation_response, self(), "c1", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}}, {:queue_cell_evaluation, self(), "c2"}, {:queue_cell_evaluation, self(), "c3"} ]) @@ -1708,7 +1747,8 @@ defmodule Livebook.Session.DataTest do {:insert_cell, self(), "s1", 1, :elixir, "c2"}, {:set_runtime, self(), NoopRuntime.new()}, {:queue_cell_evaluation, self(), "c2"}, - {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}} + {:add_cell_evaluation_response, self(), "c2", {:ok, [1, 2, 3]}, + %{evaluation_time_ms: 10}} ]) attrs = %{value: "stuff"} diff --git a/test/livebook/session_test.exs b/test/livebook/session_test.exs index 65fad1a56..7f7dee6a5 100644 --- a/test/livebook/session_test.exs +++ b/test/livebook/session_test.exs @@ -82,7 +82,9 @@ defmodule Livebook.SessionTest do Session.queue_cell_evaluation(session_id, cell_id) - assert_receive {:operation, {:add_cell_evaluation_response, _, ^cell_id, _}}, + assert_receive {:operation, + {:add_cell_evaluation_response, _, ^cell_id, _, + %{evaluation_time_ms: _time_ms}}}, @evaluation_wait_timeout end end @@ -376,7 +378,9 @@ defmodule Livebook.SessionTest do Session.queue_cell_evaluation(session_id, cell_id) # Give it a bit more time as this involves starting a system process. - assert_receive {:operation, {:add_cell_evaluation_response, _, ^cell_id, _}}, + assert_receive {:operation, + {:add_cell_evaluation_response, _, ^cell_id, _, + %{evaluation_time_ms: _time_ms}}}, @evaluation_wait_timeout end @@ -438,7 +442,8 @@ defmodule Livebook.SessionTest do Session.queue_cell_evaluation(session_id, cell_id) assert_receive {:operation, - {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}}}, + {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}, + %{evaluation_time_ms: _time_ms}}}, @evaluation_wait_timeout assert text_output =~ "Jake Peralta" @@ -467,7 +472,8 @@ defmodule Livebook.SessionTest do Session.queue_cell_evaluation(session_id, cell_id) assert_receive {:operation, - {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}}}, + {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}, + %{evaluation_time_ms: _time_ms}}}, @evaluation_wait_timeout assert text_output =~ "no matching Livebook input found" @@ -498,7 +504,8 @@ defmodule Livebook.SessionTest do Session.queue_cell_evaluation(session_id, cell_id) assert_receive {:operation, - {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}}}, + {:add_cell_evaluation_response, _, ^cell_id, {:text, text_output}, + %{evaluation_time_ms: _time_ms}}}, @evaluation_wait_timeout assert text_output =~ "no matching Livebook input found"