From 7d78cc578cafb6963aad9beec6db575f3dd4622d Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?=E8=A5=BF=E7=93=9C=C2=B0?= <wxh_email@yeah.net>
Date: Thu, 4 Jun 2026 19:46:51 +0800
Subject: [PATCH] chore: add calc timing logs

---
 backend/services/calc_service.py        | 19 ++++++++++++++++++-
 backend/tests/unit/test_calc_service.py | 11 +++++++++++
 2 files changed, 29 insertions(+), 1 deletion(-)

diff --git a/backend/services/calc_service.py b/backend/services/calc_service.py
index 1ea3ec08..d4c1cb3a 100644
--- a/backend/services/calc_service.py
+++ b/backend/services/calc_service.py
@@ -1,10 +1,27 @@
+import logging
+import time
 from typing import Any
 
 from api.core.Auth import AlterState
 from core.basic.character import createCharacter
 
 
+logger = logging.getLogger('dcalc.calc')
+
+
 def calculate(state: AlterState, config: dict[str, Any] | None) -> dict[str, Any]:
+    started_at = time.perf_counter()
     safe_config = config or {}
     character = createCharacter(state.alter, state.equVersion)
-    return character.calc(safe_config)
+    created_at = time.perf_counter()
+    result = character.calc(safe_config)
+    finished_at = time.perf_counter()
+    logger.info(
+        'calc completed alter=%s equVersion=%s create_ms=%.2f calc_ms=%.2f total_ms=%.2f',
+        state.alter,
+        state.equVersion,
+        (created_at - started_at) * 1000,
+        (finished_at - created_at) * 1000,
+        (finished_at - started_at) * 1000,
+    )
+    return result
diff --git a/backend/tests/unit/test_calc_service.py b/backend/tests/unit/test_calc_service.py
index df3254fd..d96a1430 100644
--- a/backend/tests/unit/test_calc_service.py
+++ b/backend/tests/unit/test_calc_service.py
@@ -1,3 +1,5 @@
+import logging
+
 from api.core.Auth import AlterState
 from services.calc_service import calculate
 
@@ -9,3 +11,12 @@ def test_calculate_returns_character_calc_result(minimal_calc_config):
 
     assert isinstance(result, dict)
     assert set(['uuid', 'skills', 'info', 'suits', 'buffer']).issubset(result)
+
+
+def test_calculate_logs_timing(caplog, minimal_calc_config):
+    state = AlterState('GF.swordman_male.weapon_master', 'token', {}, '0', 0)
+
+    with caplog.at_level(logging.INFO, logger='dcalc.calc'):
+        calculate(state, minimal_calc_config)
+
+    assert any('calc completed alter=GF.swordman_male.weapon_master' in record.message for record in caplog.records)