perf: 量化商品页打开耗时并去重检查 (#109)

client/test/test_pdd_collect_service.py

@@ -34,6 +34,7 @@ class FakeCollectDevice:
         self.clicks = []
         self.swipes = []
         self.swipe_panel_states = []
+        self.app_wait_calls = 0
 
     def app_current(self):
         return {"package": "com.xunmeng.pinduoduo"}
@@ -42,6 +43,7 @@ class FakeCollectDevice:
         raise AssertionError("PDD 已经在前台，不应重复启动")
 
     def app_wait(self, _package, timeout=10):
+        self.app_wait_calls += 1
         return 123
 
     def open_url(self, url):
@@ -424,6 +426,7 @@ class PddCollectParserTest(unittest.TestCase):
         )
         self.assertEqual(data["source"]["device_address"], "USB-001")
         self.assertIsNone(data["purchase"])
+        self.assertEqual(device.app_wait_calls, 0)
 
     def test_collect_scrolls_before_spec_panel_and_accumulates_metadata(self):
         initial_page = self.home_xml.replace(
@@ -510,6 +513,7 @@ class PddCollectParserTest(unittest.TestCase):
 
         self.assertEqual(result.goods_id, "123")
         self.assertTrue(device.app_started)
+        self.assertEqual(device.app_wait_calls, 1)
 
     def test_price_is_sampled_once_per_available_color(self):
         device = FakeCollectDevice(self.home_xml, self.spec_xml)

client/test/test_pdd_device_service.py

@@ -4,10 +4,15 @@ import threading
 import unittest
 
 from src.pdd_device_service import PddDeviceError, PddDeviceService
+from src.performance_timing import TaskPerformanceTrace
 
 
 class FakeDevice:
+    def __init__(self):
+        self.current_calls = 0
+
     def app_current(self):
+        self.current_calls += 1
         return {"package": "com.xunmeng.pinduoduo"}
 
 
@@ -25,6 +30,25 @@ class PddDeviceServiceTest(unittest.TestCase):
             pass
         self.assertEqual(connected, ["USB-001", "USB-002"])
 
+    def test_connect_exposes_initial_state_and_records_two_separate_stages(self):
+        device = FakeDevice()
+        records = []
+        trace = TaskPerformanceTrace(sink=records.append)
+        trace.bind_task("COL-001")
+
+        with trace.activate():
+            session = PddDeviceService(lambda _serial: device).connect("USB-001")
+        self.assertEqual(
+            session.initial_app_state["package"],
+            "com.xunmeng.pinduoduo",
+        )
+        self.assertEqual(device.current_calls, 1)
+        self.assertEqual(
+            [record["operation"] for record in records],
+            ["uiautomator2_connect", "first_app_current"],
+        )
+        session.__exit__(None, None, None)
+
     def test_invalid_serial_is_rejected_before_connect(self):
         with self.assertRaisesRegex(PddDeviceError, "设备号无效") as raised:
             PddDeviceService(lambda _serial: FakeDevice()).connect("bad serial")

client/test/test_pdd_u2_purchase_adapter.py

@@ -59,6 +59,7 @@ class FakeDevice:
         self.quantity = 1
         self.clicks = []
         self.opened_urls = []
+        self.app_wait_calls = 0
 
     def app_current(self):
         return {"package": "com.xunmeng.pinduoduo"}
@@ -67,6 +68,7 @@ class FakeDevice:
         pass
 
     def app_wait(self, _package, timeout=10):
+        self.app_wait_calls += 1
         return True
 
     def open_url(self, url):
@@ -87,6 +89,25 @@ class FakeDevice:
         raise AssertionError(f"未预期的 selector: {selector}")
 
 
+class ColdStartDevice(FakeDevice):
+    def __init__(self) -> None:
+        super().__init__()
+        self.current_calls = 0
+        self.app_started = False
+
+    def app_current(self):
+        self.current_calls += 1
+        package = (
+            "com.android.launcher"
+            if self.current_calls == 1
+            else "com.xunmeng.pinduoduo"
+        )
+        return {"package": package}
+
+    def app_start(self, _package):
+        self.app_started = True
+
+
 class U2PddPurchaseAdapterTest(unittest.TestCase):
     def _adapter(self, device, calls):
         def select_color_fn(_device, _xml, target, **_kwargs):
@@ -150,6 +171,7 @@ class U2PddPurchaseAdapterTest(unittest.TestCase):
         self.assertEqual(calls, [("color", "黑色"), ("size", "3XL【140-165斤】")])
         # 只点击一次商品页采购入口；最终“提交订单”从不点击。
         self.assertEqual(len(device.clicks), 1)
+        self.assertEqual(device.app_wait_calls, 0)
 
     def test_unsupported_dynamic_option_stops_before_click(self):
         device = FakeDevice()
@@ -163,6 +185,16 @@ class U2PddPurchaseAdapterTest(unittest.TestCase):
         self.assertEqual(device.clicks, [])
         adapter.close()
 
+    def test_cold_start_waits_for_pdd_once(self):
+        device = ColdStartDevice()
+        adapter = self._adapter(device, [])
+
+        adapter.open_goods(GOODS_URL)
+
+        self.assertTrue(device.app_started)
+        self.assertEqual(device.app_wait_calls, 1)
+        adapter.close()
+
     def test_captcha_stops_without_waiting_or_clicking(self):
         device = FakeDevice(
             '<hierarchy><node package="com.xunmeng.pinduoduo" '

client/test/test_performance_timing.py

@@ -0,0 +1,107 @@
+"""任务性能计时测试，不连接设备。"""
+
+import json
+import logging
+import tempfile
+import unittest
+from pathlib import Path
+
+from src.performance_timing import (
+    TaskPerformanceTrace,
+    configure_performance_logging,
+    current_performance_trace,
+)
+
+
+class MutableClock:
+    def __init__(self) -> None:
+        self.value = 10.0
+
+    def __call__(self) -> float:
+        return self.value
+
+
+class TaskPerformanceTraceTest(unittest.TestCase):
+    def test_stages_are_monotonic_scoped_and_use_only_safe_fields(self):
+        clock = MutableClock()
+        records = []
+        trace = TaskPerformanceTrace(monotonic=clock, sink=records.append)
+
+        with trace.activate():
+            self.assertIs(current_performance_trace(), trace)
+            with trace.stage("admin_claim_request"):
+                clock.value = 10.125
+            trace.bind_task("COL-001")
+            clock.value = 10.250
+            trace.checkpoint("end_to_end_total")
+
+        self.assertIsNone(current_performance_trace())
+        self.assertEqual(
+            records,
+            [
+                {
+                    "task_id": "COL-001",
+                    "operation": "admin_claim_request",
+                    "duration_ms": 125,
+                    "result": "succeeded",
+                },
+                {
+                    "task_id": "COL-001",
+                    "operation": "end_to_end_total",
+                    "duration_ms": 250,
+                    "result": "succeeded",
+                },
+            ],
+        )
+        self.assertEqual(
+            set(records[0]),
+            {"task_id", "operation", "duration_ms", "result"},
+        )
+
+    def test_negative_duration_is_clamped_and_cross_task_reuse_is_rejected(self):
+        records = []
+        trace = TaskPerformanceTrace(sink=records.append)
+        trace.bind_task("COL-001")
+        trace.record("sqlite_local_save", -1, "succeeded")
+
+        self.assertEqual(records[0]["duration_ms"], 0)
+        with self.assertRaisesRegex(RuntimeError, "不能跨任务"):
+            trace.bind_task("COL-002")
+
+    def test_failed_stage_does_not_log_exception_details(self):
+        records = []
+        trace = TaskPerformanceTrace(sink=records.append)
+        trace.bind_task("COL-SECRET")
+
+        with self.assertRaisesRegex(RuntimeError, "token-secret"):
+            with trace.stage("open_url"):
+                raise RuntimeError("token-secret")
+
+        self.assertEqual(records[0]["result"], "failed")
+        self.assertNotIn("token-secret", str(records[0]))
+
+    def test_configured_jsonl_log_can_be_viewed_and_has_safe_schema(self):
+        with tempfile.TemporaryDirectory() as temporary:
+            path = configure_performance_logging(Path(temporary))
+            trace = TaskPerformanceTrace()
+            trace.bind_task("COL-001")
+            trace.record("first_app_current", 0.125, "succeeded")
+
+            logger = logging.getLogger("cmautobuy.performance")
+            for handler in logger.handlers:
+                handler.flush()
+            record = json.loads(path.read_text(encoding="utf-8").strip())
+            self.assertEqual(record["duration_ms"], 125)
+            self.assertEqual(
+                set(record),
+                {"task_id", "operation", "duration_ms", "result"},
+            )
+
+            for handler in list(logger.handlers):
+                if getattr(handler, "baseFilename", None) == str(path.resolve()):
+                    logger.removeHandler(handler)
+                    handler.close()
+
+
+if __name__ == "__main__":
+    unittest.main()

client/test/test_task_dispatcher.py

@@ -12,6 +12,7 @@ from src.pdd_purchase_adapter import (
     PddPurchaseAdapter,
     PurchasePageState,
 )
+from src.performance_timing import TaskPerformanceTrace
 from src.task_dispatcher import TaskDispatcher, admin_task_to_new_claimed_task
 from src.task_models import TaskStatus, TaskType
 from src.task_repository import TaskRepository
@@ -134,6 +135,7 @@ class TaskDispatcherTest(unittest.TestCase):
         purchase_mode="dry_run",
         device_checker=lambda _serial: None,
         task_saved=lambda _task_id: None,
+        performance_trace_factory=TaskPerformanceTrace,
     ):
         purchase_factory = None
         if purchase_ready:
@@ -161,8 +163,30 @@ class TaskDispatcherTest(unittest.TestCase):
             purchase_mode=purchase_mode,
             device_connection_checker=device_checker,
             task_saved=task_saved,
+            performance_trace_factory=performance_trace_factory,
         )
 
+    def test_claim_save_and_device_check_have_scoped_timing_records(self):
+        task = purchase_task()
+        self.gateway.enqueue_task(task, self.client.client_id)
+        records = []
+
+        outcome = self._dispatcher(
+            purchase_ready=True,
+            performance_trace_factory=lambda: TaskPerformanceTrace(
+                sink=records.append
+            ),
+        ).execute_one()
+
+        self.assertEqual(outcome.kind, "succeeded")
+        operations = [record["operation"] for record in records]
+        self.assertEqual(
+            operations[:3],
+            ["adb_device_check", "admin_claim_request", "sqlite_local_save"],
+        )
+        self.assertTrue(all(record["task_id"] == task.task_id for record in records))
+        self.assertTrue(all(record["duration_ms"] >= 0 for record in records))
+
     def test_capability_only_includes_purchase_when_adapter_is_ready(self):
         collect_only = self._dispatcher(purchase_ready=False)
         ready = self._dispatcher(purchase_ready=True)