1. Stage Timings: 为每个阶段耗时补充起止时间戳。

2，漏了一些重要的stage，比如「款式意图 SKU 预筛选（StyleSkuSelector.prepare_hits）」，补上这个stage

1. Stage Timings: 为每个阶段耗时补充起止时间戳。
2，漏了一些重要的stage，比如「款式意图 SKU 预筛选（StyleSkuSelector.prepare_hits）」，补上这个stage
tangwang
1 parent 4650fcec
Showing 4 changed files with 99 additions and 16 deletions Show diff stats
context/request_context.py
docs/TODO-prompts.md
frontend/static/js/app.js
search/searcher.py
@@ -27,6 +27,8 @@ class RequestContextStage(Enum):
     ELASTICSEARCH_PAGE_FILL = "elasticsearch_page_fill"
     RESULT_PROCESSING = "result_processing"
     RERANKING = "reranking"
+    # 款式意图 SKU 预筛选（StyleSkuSelector.prepare_hits）
+    STYLE_SKU_PREPARE_HITS = "style_sku_prepare_hits"
 @dataclass
@@ -48,6 +50,8 @@ class PerformanceMetrics:
     """性能指标"""
     stage_timings: Dict[str, float] = field(default_factory=dict)
     stage_start_times: Dict[str, float] = field(default_factory=dict)
+    # 各阶段起止时间（Unix 毫秒，与 time.time() 一致）
+    stage_time_bounds_ms: Dict[str, Dict[str, float]] = field(default_factory=dict)
     total_duration: float = 0.0
     extra_metrics: Dict[str, Any] = field(default_factory=dict)
@@ -141,8 +145,13 @@ class RequestContext:
             return 0.0
         start_time = self.performance_metrics.stage_start_times[stage.value]
-        duration_ms = (time.time() - start_time) * 1000
+        end_time = time.time()
+        duration_ms = (end_time - start_time) * 1000
         self.performance_metrics.stage_timings[stage.value] = duration_ms
+        self.performance_metrics.stage_time_bounds_ms[stage.value] = {
+            "start_unix_ms": round(start_time * 1000, 3),
+            "end_unix_ms": round(end_time * 1000, 3),
+        }
         self.logger.debug(
             f"End stage | {stage.value} | duration: {duration_ms:.2f}ms",
@@ -280,6 +289,12 @@ class RequestContext:
                 'stage_timings_ms': {
                     k: round(v, 2) for k, v in self.performance_metrics.stage_timings.items()
                 },
+                'stage_time_bounds_ms': {
+                    stage: {
+                        kk: round(vv, 3) for kk, vv in bounds.items()
+                    }
+                    for stage, bounds in self.performance_metrics.stage_time_bounds_ms.items()
+                },
                 'stage_percentages': self.calculate_stage_percentages()
             },
             'results': {
@@ -307,9 +322,17 @@ class RequestContext:
         # 添加各阶段耗时
         if summary['performance']['stage_timings_ms']:
             msg_parts.append("Stage durations:")
+            bounds_map = summary['performance'].get('stage_time_bounds_ms') or {}
             for stage, duration in summary['performance']['stage_timings_ms'].items():
                 percentage = summary['performance']['stage_percentages'].get(stage, 0)
-                msg_parts.append(f"  - {stage}: {duration:.2f}ms ({percentage}%)")
+                b = bounds_map.get(stage) or {}
+                if b.get('start_unix_ms') is not None and b.get('end_unix_ms') is not None:
+                    msg_parts.append(
+                        f"  - {stage}: {duration:.2f}ms ({percentage}%) "
+                        f"[{b['start_unix_ms']:.3f} -> {b['end_unix_ms']:.3f} ms]"
+                    )
+                else:
+                    msg_parts.append(f"  - {stage}: {duration:.2f}ms ({percentage}%)")
         # 添加查询信息
         if summary['query_analysis']['original_query']:
@@ -0,0 +1,39 @@
+
+1. debug信息展示方面
+在这次重构过程中，你基本上了解了从query析到 ES 搜索，再到重排的全流程。
+在这些环节中，有哪些重要的信息对搜索结果产生较大影响，先回顾，适当的完善、优化日志。
+debug_info也给前端更充分的调试信息，包括，丰富每条结果的ranking debug。目前只有这些
+Ranking Debug
+spu_id
+ES score
+ES normalized
+ES norm (rerank input):
+Rerank score
+Fused score
+title.en
+title.zh
+
+还不够，需要详细思考，设计一个更加完整的展示的体系
+比如：
+position（重排前的，重排后最终的）
+ES打分，从ES检索原始打分、相关的因子（minmax归一化的因子。到底用了哪些因子，你自己关注下，用到的要体现出来，让人知道从原始打分怎么得到的ES norm (rerank input)）。另外ES normalized，ES norm，要梳理清楚，如果代码不清晰则改代码，展示不清晰则要梳理展示。
+Rerank这一块，除了rerank_score，输入的信息比如输入的doc模板，被选中的sku及其用于辅助reranker相关性的、加到title后面的后缀
+融合公式这一块，除了fused_score，还要包含rerank_factor, text_factor, knn_factor等因子，以及text_score, knn_score, text_source_score, text_translation_score, …	等变量，要清晰的展示。
+证据	matched_queries	
+
+
+耗时记录方面：
+1. Stage Timings: 为每个阶段耗时补充起止时间戳。
+2， 我看到total_search大幅度大于上面各个Stage 的总和，可能漏了一些重要的stage，比如「款式意图 SKU 预筛选（StyleSkuSelector.prepare_hits）」，补上这个stage
+
+但是也要注意，不要影响不带debug_info的请求的性能。
+
+
+2. 日志方面也需要完善
+从 query 到 ES 再到重排，对结果影响大的信息，语种检测 + index_languages，Query 向量，ES查询的构建过程中所使用的关键的变量、关键的中间结果，rerank相关信息（intput/window，query/doc 模板，融合公式的详细信息和关键的因子、输入原始值以及中间变量、到最终的融合公式的因子，Page fill，sku_filter_dimension等
+
+
+3. 测试用例方面
+子串匹配（Direct 阶段）是否可能产生误判 — 与尺码/短词强相关
+_is_direct_match 使用 normalized_value in query_text（见 sku_intent_selector.py）。
+词表里 l、m、s、xl，会在常见英文 query 里产生字符级子串命中，例如"l" 是否会匹配 "large …" 里的 l，注意要用分词匹配，检查分词匹配逻辑是否容易产生badcase。
@@ -927,8 +927,14 @@ function displayDebugInfo(data) {
     // Stage Timings
     if (debugInfo.stage_timings) {
         html += '<div style="margin-bottom: 15px;"><strong style="font-size: 14px;">Stage Timings:</strong>';
+        const bounds = debugInfo.stage_time_bounds_ms || {};
         for (const [stage, duration] of Object.entries(debugInfo.stage_timings)) {
-            html += `<div>${stage}: ${duration.toFixed(2)}ms</div>`;
+            const b = bounds[stage];
+            if (b && b.start_unix_ms != null && b.end_unix_ms != null) {
+                html += `<div>${stage}: ${Number(duration).toFixed(2)}ms <span style="color:#666">(start ${b.start_unix_ms} → end ${b.end_unix_ms} unix ms)</span></div>`;
+            } else {
+                html += `<div>${stage}: ${Number(duration).toFixed(2)}ms</div>`;
+            }
         }
         html += '</div>';
     }
@@ -256,13 +256,19 @@ class Searcher:
         parsed_query: ParsedQuery,
         context: Optional[RequestContext] = None,
     ) -> Dict[str, SkuSelectionDecision]:
-        decisions = self.style_sku_selector.prepare_hits(es_hits, parsed_query)
-        if decisions and context is not None:
-            context.store_intermediate_result(
-                "style_intent_sku_decisions",
-                {doc_id: decision.to_dict() for doc_id, decision in decisions.items()},
-            )
-        return decisions
+        if context is not None:
+            context.start_stage(RequestContextStage.STYLE_SKU_PREPARE_HITS)
+        try:
+            decisions = self.style_sku_selector.prepare_hits(es_hits, parsed_query)
+            if decisions and context is not None:
+                context.store_intermediate_result(
+                    "style_intent_sku_decisions",
+                    {doc_id: decision.to_dict() for doc_id, decision in decisions.items()},
+                )
+            return decisions
+        finally:
+            if context is not None:
+                context.end_stage(RequestContextStage.STYLE_SKU_PREPARE_HITS)
     def search(
         self,
@@ -667,6 +673,15 @@ class Searcher:
                 extra={'reqid': context.reqid, 'uid': context.uid}
             )
+        # 非重排窗口：款式意图在 result_processing 之前执行，便于单独计时且与 ES 召回阶段衔接
+        if self._has_style_intent(parsed_query) and not in_rerank_window:
+            es_hits_pre = es_response.get("hits", {}).get("hits") or []
+            style_intent_decisions = self._apply_style_intent_to_hits(
+                es_hits_pre,
+                parsed_query,
+                context=context,
+            )
+
         # Step 5: Result processing
         context.start_stage(RequestContextStage.RESULT_PROCESSING)
         try:
@@ -701,12 +716,6 @@ class Searcher:
                         es_hits,
                         style_intent_decisions,
                     )
-                elif not in_rerank_window:
-                    style_intent_decisions = self._apply_style_intent_to_hits(
-                        es_hits,
-                        parsed_query,
-                        context=context,
-                    )
             # Format results using ResultFormatter
             formatted_results = ResultFormatter.format_search_results(
@@ -832,6 +841,12 @@ class Searcher:
                 "stage_timings": {
                     k: round(v, 2) for k, v in context.performance_metrics.stage_timings.items()
                 },
+                "stage_time_bounds_ms": {
+                    stage: {
+                        kk: round(vv, 3) for kk, vv in bounds.items()
+                    }
+                    for stage, bounds in context.performance_metrics.stage_time_bounds_ms.items()
+                },
                 "search_params": context.metadata.get('search_params', {})
             }
             if per_result_debug: