Add totalTimeMs to reason and toolCall content blocks.

Author: ericdallo

CHANGELOG.md

@@ -2,6 +2,8 @@
 
 ## Unreleased
 
+- Add `totalTimeMs` to reason and toolCall content blocks.
+
 ## 0.48.0
 
 - Add nix flake build.

docs/protocol.md

@@ -468,6 +468,11 @@ interface ReasonFinishedContent {
      * The id of this reason
      */
     id: string; 
+
+    /**
+     * The total time the reason took in milliseconds.
+     */
+    totalTimeMs: number;
 }
 
 /**
@@ -681,6 +686,11 @@ interface ToolCalledContent {
         text: string; 
     }];
 
+    /**
+     * The total time the call took in milliseconds.
+     */
+    totalTimeMs: number;
+    
     /**
      * Summary text to present about this tool call, 
      * ex: 'Reading file "foo"...'.

integration-test/entrypoint.clj

@@ -5,7 +5,7 @@
    [llm-mock.server :as llm-mock.server]))
 
 (def namespaces
-  '[integration.initialize-test
+  '[;integration.initialize-test
     integration.chat.openai-test
     integration.chat.anthropic-test
     integration.chat.github-copilot-test

integration-test/integration/chat/anthropic_test.clj

@@ -132,7 +132,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " hello"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "hello"})
         (match-content chat-id "assistant" {:type "text" :text " there!"})
         (match-content chat-id "system" {:type "usage"
@@ -165,7 +165,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " fine"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "I'm "})
         (match-content chat-id "assistant" {:type "text" :text " fine"})
         (match-content chat-id "system" {:type "usage"
@@ -209,7 +209,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should call tool"})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " eca_directory_tree"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "I will list files"})
         (match-content chat-id "assistant" {:type "toolCallPrepare"
                                             :origin "native"
@@ -252,6 +252,7 @@
                                             :name "eca_directory_tree"
                                             :arguments {:path (h/project-path->canon-path "resources")}
                                             :summary "Listing file tree"
+                                            :totalTimeMs (m/pred number?)
                                             :error false
                                             :outputs [{:type "text" :text (str "├── file1.md\n"
                                                                                "└── file2.md\n\n"

integration-test/integration/chat/github_copilot_test.clj

@@ -123,7 +123,7 @@
           (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " hello"})
-          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
           (match-content chat-id "assistant" {:type "text" :text "hello"})
           (match-content chat-id "assistant" {:type "text" :text " there!"})
           (match-content chat-id "system" {:type "usage"
@@ -158,7 +158,7 @@
           (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " fine"})
-          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
           (match-content chat-id "assistant" {:type "text" :text "I'm "})
           (match-content chat-id "assistant" {:type "text" :text " fine"})
           (match-content chat-id "system" {:type "usage"
@@ -207,7 +207,7 @@
           (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should call tool"})
           (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " eca_directory_tree"})
-          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+          (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
           (match-content chat-id "assistant" {:type "text" :text "I will list files"})
           (match-content chat-id "assistant" {:type "toolCallPrepare"
                                               :origin "native"
@@ -248,6 +248,7 @@
                                               :id "tool-1"
                                               :name "eca_directory_tree"
                                               :arguments {:path (h/project-path->canon-path "resources")}
+                                              :totalTimeMs number?
                                               :summary "Listing file tree"})
           (match-content chat-id "assistant" {:type "toolCalled"
                                               :origin "native"

integration-test/integration/chat/ollama_test.clj

@@ -134,7 +134,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " hello"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "hello"})
         (match-content chat-id "assistant" {:type "text" :text " there!"})
         (match-content chat-id "system" {:type "progress" :state "finished"})
@@ -164,7 +164,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id (m/pred string?)})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id (m/pred string?) :text " fine"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?)})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id (m/pred string?) :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "I'm "})
         (match-content chat-id "assistant" {:type "text" :text " fine"})
         (match-content chat-id "system" {:type "progress" :state "finished"})
@@ -233,6 +233,7 @@
                                             :name "eca_directory_tree"
                                             :arguments {:path (h/project-path->canon-path "resources")}
                                             :summary "Listing file tree"
+                                            :totalTimeMs (m/pred number?)
                                             :error false
                                             :outputs [{:type "text" :text (str "├── file1.md\n"
                                                                                "└── file2.md\n\n"

integration-test/integration/chat/openai_test.clj

@@ -132,7 +132,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id "123"})
         (match-content chat-id "assistant" {:type "reasonText" :id "123" :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id "123" :text " hello"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id "123"})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id "123" :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "hello"})
         (match-content chat-id "assistant" {:type "text" :text " there!"})
         (match-content chat-id "system" {:type "usage"
@@ -165,7 +165,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id "234"})
         (match-content chat-id "assistant" {:type "reasonText" :id "234" :text "I should say"})
         (match-content chat-id "assistant" {:type "reasonText" :id "234" :text " fine"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id "234"})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id "234" :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "I'm "})
         (match-content chat-id "assistant" {:type "text" :text " fine"})
         (match-content chat-id "system" {:type "usage"
@@ -209,7 +209,7 @@
         (match-content chat-id "assistant" {:type "reasonStarted" :id "123"})
         (match-content chat-id "assistant" {:type "reasonText" :id "123" :text "I should call tool"})
         (match-content chat-id "assistant" {:type "reasonText" :id "123" :text " eca_directory_tree"})
-        (match-content chat-id "assistant" {:type "reasonFinished" :id "123"})
+        (match-content chat-id "assistant" {:type "reasonFinished" :id "123" :totalTimeMs (m/pred number?)})
         (match-content chat-id "assistant" {:type "text" :text "I will list files"})
         (match-content chat-id "assistant" {:type "toolCallPrepare"
                                             :origin "native"
@@ -252,6 +252,7 @@
                                             :name "eca_directory_tree"
                                             :arguments {:path (h/project-path->canon-path "resources")}
                                             :summary "Listing file tree"
+                                            :totalTimeMs (m/pred number?)
                                             :error false
                                             :outputs [{:type "text" :text (str "├── file1.md\n"
                                                                                "└── file2.md\n\n"

src/eca/features/chat.clj

@@ -132,7 +132,7 @@
 
    [:execution-approved :execution-start]
    {:status :executing
-    :actions [:send-toolCallRunning]}
+    :actions [:set-start-time :send-toolCallRunning]}
 
    [:executing :execution-end]
    {:status :completed
@@ -216,6 +216,7 @@
                      :name (:name event-data)
                      :arguments (:arguments event-data)
                      :error (:error event-data)
+                     :total-time-ms (:total-time-ms event-data)
                      :outputs (:outputs event-data)}
                     :details (:details event-data)
                     :summary (:summary event-data)))
@@ -254,6 +255,10 @@
     (swap! db* assoc-in [:chats (:chat-id chat-ctx) :tool-calls tool-call-id :decision-reason]
            (:reason event-data))
 
+    :set-start-time
+    (swap! db* assoc-in [:chats (:chat-id chat-ctx) :tool-calls tool-call-id :start-time]
+           (:start-time event-data))
+
     ;; Logging actions
     :log-rejection
     (logger/info logger-tag "Tool call rejected"
@@ -379,7 +384,7 @@
         past-messages (get-in db [:chats chat-id :messages] [])
         all-tools (f.tools/all-tools behavior @db* config)
         received-msgs* (atom "")
-        received-thinking* (atom "")
+        reasonings* (atom {})
         add-to-history! (fn [msg]
                           (swap! db* update-in [:chats chat-id :messages] (fnil conj []) msg))]
     (when-let [expires-at (get-in db [:auth provider :expires-at])]
@@ -494,11 +499,13 @@
                                                                        {:origin origin
                                                                         :name name
                                                                         :arguments arguments
+                                                                        :start-time (System/currentTimeMillis)
                                                                         :details details
                                                                         :summary summary})
                                                 ;; assert: In :executing
                                                 (let [result (f.tools/call-tool! name arguments @db* config messenger behavior)
-                                                      details (f.tools/tool-call-details-after-invocation name arguments details result)]
+                                                      details (f.tools/tool-call-details-after-invocation name arguments details result)
+                                                      {:keys [start-time]} (get-tool-call-state @db* chat-id id)]
                                                   (add-to-history! {:role "tool_call" :content (assoc tool-call
                                                                                                       :details details
                                                                                                       :summary summary
@@ -515,6 +522,7 @@
                                                                           :arguments arguments
                                                                           :error (:error result)
                                                                           :outputs (:contents result)
+                                                                          :total-time-ms (- (System/currentTimeMillis) start-time)
                                                                           :details details
                                                                           :summary summary})))
                                               ;; assert: In :rejected state
@@ -540,21 +548,24 @@
       :on-reason (fn [{:keys [status id text external-id]}]
                    (assert-chat-not-stopped! chat-ctx)
                    (case status
-                     :started (send-content! chat-ctx :assistant
-                                             {:type :reasonStarted
-                                              :id id})
+                     :started (do
+                                (swap! reasonings* assoc-in [id :start-time] (System/currentTimeMillis))
+                                (send-content! chat-ctx :assistant
+                                               {:type :reasonStarted
+                                                :id id}))
                      :thinking (do
-                                 (swap! received-thinking* str text)
+                                 (swap! reasonings* update-in [id :text] str text)
                                  (send-content! chat-ctx :assistant
                                                 {:type :reasonText
                                                  :id id
                                                  :text text}))
                      :finished (do
                                  (add-to-history! {:role "reason" :content {:id id
                                                                             :external-id external-id
-                                                                            :text @received-thinking*}})
+                                                                            :text (get-in @reasonings* [id :text])}})
                                  (send-content! chat-ctx :assistant
                                                 {:type :reasonFinished
+                                                 :total-time-ms (- (System/currentTimeMillis) (get-in @reasonings* [id :start-time]))
                                                  :id id}))
                      nil))
       :on-error (fn [{:keys [message exception]}]

test/eca/features/chat_test.clj

@@ -212,7 +212,7 @@
              {:role :assistant :content {:type :toolCallPrepare :id "call-1" :name "list_allowed_directories" :arguments-text ""}}
              {:role :assistant :content {:type :toolCallRun :id "call-1" :name "list_allowed_directories" :arguments {} :manual-approval false}}
              {:role :assistant :content {:type :toolCallRunning :id "call-1" :name "list_allowed_directories" :arguments {}}}
-             {:role :assistant :content {:type :toolCalled :id "call-1" :name "list_allowed_directories" :arguments {} :outputs [{:content "Allowed directories: /foo/bar" :type :text}]}}
+             {:role :assistant :content {:type :toolCalled :id "call-1" :name "list_allowed_directories" :arguments {} :total-time-ms number? :outputs [{:content "Allowed directories: /foo/bar" :type :text}]}}
              {:role :system :content {:type :progress :state :running :text "Generating"}}
              {:role :assistant :content {:type :text :text "I can see: \n"}}
              {:role :assistant :content {:type :text :text "/foo/bar"}}

test/eca/features/chat_tool_call_state_test.clj

@@ -408,7 +408,7 @@
         (let [result (#'f.chat/transition-tool-call! db* chat-ctx tool-call-id :execution-start
                                                      {:name "list_files" :origin "filesystem" :arguments {:path "/tmp"}})]
           (is (match? {:status :executing
-                       :actions [:send-toolCallRunning]}
+                       :actions [:set-start-time :send-toolCallRunning]}
                       result)
               "Expected transition to :executing status with no additional actions")