time logging hinzugefügt

math-tutor/backend/app/deterministic_services/orchestrators/orchestrator_QA.py

@@ -19,9 +19,12 @@ def _on_build_reply(state: base.ChatState) -> str | None:
         "history": context_store.format_history(state.messages),
         "sources": "\n".join([source.to_string() for source in context_store.get_retrieval(state.sheet)]),
     }
-    reply = qa_LLM.answer_question(**args)
-    base.append_tool_log(state.tool_log, "answer_question", args, reply)
-    return reply
+    return base.log_timed_call(
+        state.tool_log,
+        "answer_question",
+        args,
+        lambda: qa_LLM.answer_question(**args),
+    )
 
 
 def run_chat(messages: list[dict], draft: str | None = None) -> dict:

math-tutor/backend/app/deterministic_services/orchestrators/orchestrator_base.py

 from __future__ import annotations
 
+import time
 from dataclasses import dataclass
-from typing import Callable, List
+from datetime import datetime, timezone
+from typing import Callable, List, TypeVar
 
 import app.config as config
 from app.deterministic_services import (
@@ -14,6 +16,9 @@ from app.deterministic_services import (
 from app.deterministic_services.embeddings import EmbeddingFactory
 
 
+T = TypeVar("T")
+
+
 @dataclass
 class ChatState:
     messages: list[dict]
@@ -29,8 +34,73 @@ def is_new_chat(messages: list[dict]) -> bool:
     return not any(m.get("role") == "assistant" for m in messages)
 
 
-def append_tool_log(tool_log: list[dict], name: str, args: dict, response: object) -> None:
-    tool_log.append({"name": name, "arguments": args, "response": response})
+def _utc_now_iso() -> str:
+    return datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ")
+
+
+def _start_timing() -> tuple[str, float]:
+    return _utc_now_iso(), time.perf_counter()
+
+
+def _finish_timing(started_perf: float) -> tuple[str, float]:
+    finished_at = _utc_now_iso()
+    duration_ms = round((time.perf_counter() - started_perf) * 1000, 2)
+    return finished_at, duration_ms
+
+
+def append_tool_log(
+    tool_log: list[dict],
+    name: str,
+    args: dict,
+    response: object,
+    *,
+    started_at: str | None = None,
+    finished_at: str | None = None,
+    duration_ms: float | None = None,
+) -> None:
+    entry = {"name": name, "arguments": args, "response": response}
+    if started_at is not None:
+        entry["started_at"] = started_at
+    if finished_at is not None:
+        entry["finished_at"] = finished_at
+    if duration_ms is not None:
+        entry["duration_ms"] = duration_ms
+    tool_log.append(entry)
+
+
+def log_timed_call(
+    tool_log: list[dict],
+    name: str,
+    args: dict,
+    call: Callable[[], T],
+) -> T:
+    started_at, started_perf = _start_timing()
+    try:
+        response = call()
+    except Exception as exc:
+        finished_at, duration_ms = _finish_timing(started_perf)
+        append_tool_log(
+            tool_log,
+            name,
+            args,
+            {"error": str(exc)},
+            started_at=started_at,
+            finished_at=finished_at,
+            duration_ms=duration_ms,
+        )
+        raise
+
+    finished_at, duration_ms = _finish_timing(started_perf)
+    append_tool_log(
+        tool_log,
+        name,
+        args,
+        response,
+        started_at=started_at,
+        finished_at=finished_at,
+        duration_ms=duration_ms,
+    )
+    return response
 
 
 def extract_user_messages(messages: list[dict]) -> list[str]:
@@ -56,12 +126,32 @@ def retrieve_context(query_text: str, pg_url: str | None = None) -> List[Source]
 
 
 def bootstrap_retrieval(sheet: dict, query_text: str, tool_log: list[dict]) -> None:
+    started_at, started_perf = _start_timing()
     sources = retrieve_context(query_text=query_text)
+    finished_at, duration_ms = _finish_timing(started_perf)
     source_dump = {"sources": [source.to_string() for source in sources]}
+    append_tool_log(
+        tool_log,
+        "retrieve_context",
+        {"query": query_text},
+        source_dump,
+        started_at=started_at,
+        finished_at=finished_at,
+        duration_ms=duration_ms,
+    )
 
+    started_at, started_perf = _start_timing()
     context_store.update_retrieval_context(sheet, sources)
-    append_tool_log(tool_log, "update_retrieve_context",
-                    {"query": query_text}, source_dump)
+    finished_at, duration_ms = _finish_timing(started_perf)
+    append_tool_log(
+        tool_log,
+        "update_retrieve_context",
+        {"query": query_text},
+        source_dump,
+        started_at=started_at,
+        finished_at=finished_at,
+        duration_ms=duration_ms,
+    )
 
 
 def init_chat_state(messages: list[dict], draft: str | None = None) -> ChatState:
@@ -116,12 +206,38 @@ def run_chat_common(
     on_turn_logic: Callable[[ChatState], None],
     on_build_reply: Callable[[ChatState], str | None],
 ) -> dict:
+    init_started_at, init_started_perf = _start_timing()
     state = init_chat_state(messages, draft)
+    init_finished_at, init_duration_ms = _finish_timing(init_started_perf)
+    append_tool_log(
+        state.tool_log,
+        "orchestrator_init_state",
+        {"message_count": len(messages), "has_draft": draft is not None},
+        {"chat_id": state.chat_id, "new_chat": state.new_chat},
+        started_at=init_started_at,
+        finished_at=init_finished_at,
+        duration_ms=init_duration_ms,
+    )
 
     if state.new_chat or not state.sheet.get("initialized"):
-        on_bootstrap(state, state.last_user)
+        log_timed_call(
+            state.tool_log,
+            "orchestrator_bootstrap",
+            {"query": state.last_user},
+            lambda: on_bootstrap(state, state.last_user),
+        )
         state.sheet["initialized"] = True
 
-    on_turn_logic(state)
-    reply = on_build_reply(state)
+    log_timed_call(
+        state.tool_log,
+        "orchestrator_turn_logic",
+        {"new_chat": state.new_chat},
+        lambda: on_turn_logic(state),
+    )
+    reply = log_timed_call(
+        state.tool_log,
+        "orchestrator_build_reply",
+        {"chat_id": state.chat_id},
+        lambda: on_build_reply(state),
+    )
     return finalize_response(state, reply)

math-tutor/backend/app/deterministic_services/orchestrators/orchestrator_tutor.py

@@ -7,31 +7,35 @@ from app.deterministic_services.orchestrators import orchestrator_base as base
 
 def _on_bootstrap(state: base.ChatState, query_text: str) -> None:
     base.bootstrap_retrieval(state.sheet, query_text, state.tool_log)
-    math_solution = math_intent_LLM.solve_with_tools(query_text)
+    math_solution = base.log_timed_call(
+        state.tool_log,
+        "math_intent_LLM",
+        {"query": query_text},
+        lambda: math_intent_LLM.solve_with_tools(query_text),
+    )
     if math_solution:
         context_store.add_math_solution(state.sheet, math_solution)
-        base.append_tool_log(state.tool_log, "math_intent_LLM", {
-                             "query": query_text}, math_solution)
 
 
 def _on_turn_logic(state: base.ChatState) -> None:
-    history_turns = context_store.get_history_turns(state.sheet)
     sheet_text = context_store.format_sheet(state.sheet)
 
     if state.new_chat:
-        llm_solution = solver_LLM.solve_question(state.last_user, sheet_text)
-        base.append_tool_log(
+        llm_solution = base.log_timed_call(
             state.tool_log,
             "LLM_Solution",
             {"question": state.last_user, "sheet": sheet_text},
-            llm_solution,
+            lambda: solver_LLM.solve_question(state.last_user, sheet_text),
         )
         context_store.add_LLM_solution(state.sheet, llm_solution)
         return
 
-    decision = decision_LLM.needs_more_context(sheet_text)
-    base.append_tool_log(state.tool_log, "decision", {
-                         "sheet": sheet_text}, decision)
+    decision = base.log_timed_call(
+        state.tool_log,
+        "decision",
+        {"sheet": sheet_text},
+        lambda: decision_LLM.needs_more_context(sheet_text),
+    )
     context_store.add_decision(state.sheet, decision)
 
     if decision.get("needs_more_context"):
@@ -49,9 +53,12 @@ def _on_build_reply(state: base.ChatState) -> str | None:
         "history": history_turns,
         "sources": "\n".join([source.to_string() for source in context_store.get_retrieval(state.sheet)]),
     }
-    reply = hint_LLM.generate_hint(**args)
-    base.append_tool_log(state.tool_log, "generate_hint", args, reply)
-    return reply
+    return base.log_timed_call(
+        state.tool_log,
+        "generate_hint",
+        args,
+        lambda: hint_LLM.generate_hint(**args),
+    )
 
 
 def run_chat(messages: list[dict], draft: str | None = None) -> dict: