chore: add calc timing logs

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

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)