log how much time we spent in reasoning

Author: aviallon

tools/server/server-context.cpp

@@ -177,9 +177,11 @@ struct server_slot {
     size_t n_sent_text = 0; // number of sent text character
 
     int64_t t_start_process_prompt;
+    int64_t t_start_reasoning;
     int64_t t_start_generation;
 
     double t_prompt_processing; // ms
+    double t_reasoning_token_generation; // ms
     double t_token_generation;  // ms
 
     std::function<void(int)> callback_on_release;
@@ -394,15 +396,20 @@ struct server_slot {
         const double t_prompt        =       t_prompt_processing / n_prompt_tokens_processed;
         const double n_prompt_second = 1e3 / t_prompt_processing * n_prompt_tokens_processed;
 
+        const double t_reasoning     =       t_reasoning_token_generation / n_reasoning_tokens;
+        const double n_reasoning_second = 1e3 / t_reasoning_token_generation * n_reasoning_tokens;
+
         const double t_gen        =       t_token_generation / n_decoded;
         const double n_gen_second = 1e3 / t_token_generation * n_decoded;
 
         SLT_INF(*this,
                 "\n"
                 "prompt eval time = %10.2f ms / %5d tokens (%8.2f ms per token, %8.2f tokens per second)\n"
+                "  reasoning time = %10.2f ms / %5d tokens (%8.2f ms per token, %8.2f tokens per second)\n"
                 "       eval time = %10.2f ms / %5d tokens (%8.2f ms per token, %8.2f tokens per second)\n"
                 "      total time = %10.2f ms / %5d tokens\n",
                 t_prompt_processing, n_prompt_tokens_processed, t_prompt, n_prompt_second,
+                t_reasoning_token_generation, n_reasoning_tokens, t_reasoning, n_reasoning_second,
                 t_token_generation, n_decoded, t_gen, n_gen_second,
                 t_prompt_processing + t_token_generation, n_prompt_tokens_processed + n_decoded);
 
@@ -1200,11 +1207,12 @@ struct server_context_impl {
                     slot.reasoning = REASONING_STATE_REASONING;
                     slot.reasoning_end_tag = rstatus.end_tag;
                     slot.n_reasoning_tokens = 0;
+                    slot.t_start_reasoning = ggml_time_us();
                 }
             } else if (!rstatus.active && slot.reasoning == REASONING_STATE_REASONING) {
                 SLT_DBG(slot, "detected reasoning end '%s' via parser\n", rstatus.end_tag.c_str());
                 slot.reasoning = REASONING_STATE_FINISHED;
-                slot.n_reasoning_tokens = 0;
+                slot.t_reasoning_token_generation = (ggml_time_us() - slot.t_start_reasoning) / 1e3;
             }
 
             if (slot.reasoning == REASONING_STATE_REASONING) {
@@ -1254,7 +1262,7 @@ struct server_context_impl {
                 if (slot.forced_tokens.empty()) {
                     SLT_DBG(slot, "completed forced reasoning close with '%s'\n", slot.reasoning_end_tag.c_str());
                     slot.reasoning = REASONING_STATE_FINISHED;
-                    slot.n_reasoning_tokens = 0;
+                    slot.t_reasoning_token_generation = (ggml_time_us() - slot.t_start_reasoning) / 1e3;
                 }
             }
         }