Show the evaluation time next to the cell indicator (#366)

* Display the time in seconds

Show the evaluation time next to the cell indicator

* Test session data

* Send evaluation time to session

Start the evaluation time inside the evaluator, display the time in seconds
or milliseconds.

The output is not a string but a map

* Add metadata to evaluation_response

* Wrap the evaluation indicator in a tooltip

  • Add metadata argument to the evaluation_response message
  • Use a tooltip to display the evaluation time

* Display the toolip below the indicator

* Remove the evaluation start time

* Make the tooltip optional

* Rename finish_cell_evaluation

* Evaluator tests

* Update test to accespt metadata

* Pass the evaluated time as a third argument

* Make status tooltip more generic

Co-authored-by: Jonatan Kłosko <jonatanklosko@gmail.com>

assets/css/tooltips.css

@@ -21,6 +21,10 @@ Example usage:
   --distance: 28px;
 }
 
+.tooltip.distant-medium {
+  --distance: 10px;
+}
+
 /* Tooltip text */
 .tooltip:before {
   position: absolute;

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

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}`

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
+  def handle_info({:evaluation_response, cell_id, response, metadata}, state) do
-    operation = {:add_cell_evaluation_response, self(), cell_id, response}
+    operation = {:add_cell_evaluation_response, self(), cell_id, response, metadata}
     {:noreply, handle_operation(state, operation)}
   end
 

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
 

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
 

lib/livebook_web/live/session_live/cell_component.ex

@@ -224,7 +224,7 @@ defmodule LivebookWeb.SessionLive.CellComponent do
 
       <%= if @cell_view.type == :elixir do %>
         <div class="absolute bottom-2 right-2">
-          <%= 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) %>
         </div>
       <% end %>
     </div>
@@ -350,44 +350,49 @@ 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
+  defp render_cell_status(:evaluated, _, evaluation_time_ms) do
-    render_status_indicator("Evaluated", "bg-green-400", change_indicator: true)
+    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"""
+    <div class="<%= if(@tooltip, do: "tooltip") %> bottom distant-medium" aria-label="<%= @tooltip %>">
       <div class="flex items-center space-x-1">
-      <div class="flex text-xs text-gray-400">
+        <div class="flex text-xs text-gray-400 space-x-1">
           <%= @text %>
           <%= if @change_indicator do %>
             <span data-element="change-indicator">*</span>
@@ -400,6 +405,21 @@ defmodule LivebookWeb.SessionLive.CellComponent do
           <span class="relative inline-flex rounded-full h-3 w-3 <%= @circle_class %>"></span>
         </span>
       </div>
+    </div>
     """
   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

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

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, :evaluation1, _, %{evaluation_time_ms: _time_ms}}
-          assert_receive {:evaluation_response, :evaluation2, _}
+          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())

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"}

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"