Blame view

context/request_context.py 14.2 KB
16c42787   tangwang   feat: implement r...
1
2
3
4
5
6
7
8
9
10
11
12
13
14
  """
  请求粒度的上下文管理器
  
  用于存储查询分析结果、各检索阶段中间结果、性能指标等。
  支持线程安全的并发请求处理。
  """
  
  import time
  import threading
  from enum import Enum
  from typing import Dict, Any, Optional, List
  from dataclasses import dataclass, field
  import uuid
  
4650fcec   tangwang   日志优化、日志串联(uid rqid)
15
16
  from request_log_context import bind_request_log_context, reset_request_log_context
  
16c42787   tangwang   feat: implement r...
17
18
19
20
21
22
23
  
  class RequestContextStage(Enum):
      """搜索阶段枚举"""
      TOTAL = "total_search"
      QUERY_PARSING = "query_parsing"
      BOOLEAN_PARSING = "boolean_parsing"
      QUERY_BUILDING = "query_building"
a99e62ba   tangwang   记录各阶段耗时
24
25
26
27
      # ES 主召回查询
      ELASTICSEARCH_SEARCH_PRIMARY = "elasticsearch_search_primary"
      # ES 按 ID 回源分页详情回填
      ELASTICSEARCH_PAGE_FILL = "elasticsearch_page_fill"
16c42787   tangwang   feat: implement r...
28
29
      RESULT_PROCESSING = "result_processing"
      RERANKING = "reranking"
8ae95af0   tangwang   1. Stage Timings:...
30
31
      # 款式意图 SKU 预筛选(StyleSkuSelector.prepare_hits)
      STYLE_SKU_PREPARE_HITS = "style_sku_prepare_hits"
16c42787   tangwang   feat: implement r...
32
33
34
35
36
37
  
  
  @dataclass
  class QueryAnalysisResult:
      """查询分析结果"""
      original_query: Optional[str] = None
3a5fda00   tangwang   1. ES字段 skus的 ima...
38
      query_normalized: Optional[str] = None
16c42787   tangwang   feat: implement r...
39
40
41
42
43
44
45
46
47
48
49
50
51
52
      rewritten_query: Optional[str] = None
      detected_language: Optional[str] = None
      translations: Dict[str, str] = field(default_factory=dict)
      query_vector: Optional[List[float]] = None
      boolean_ast: Optional[str] = None
      is_simple_query: bool = True
      domain: str = "default"
  
  
  @dataclass
  class PerformanceMetrics:
      """性能指标"""
      stage_timings: Dict[str, float] = field(default_factory=dict)
      stage_start_times: Dict[str, float] = field(default_factory=dict)
8ae95af0   tangwang   1. Stage Timings:...
53
54
      # 各阶段起止时间(Unix 毫秒,与 time.time() 一致)
      stage_time_bounds_ms: Dict[str, Dict[str, float]] = field(default_factory=dict)
16c42787   tangwang   feat: implement r...
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
      total_duration: float = 0.0
      extra_metrics: Dict[str, Any] = field(default_factory=dict)
  
  
  class RequestContext:
      """
      请求粒度的上下文管理器
  
      功能:
      1. 存储查询分析结果和各阶段中间结果
      2. 自动跟踪各阶段耗时
      3. 提供线程安全的上下文访问
      4. 支持上下文管理器模式
      """
  
      def __init__(self, reqid: str = None, uid: str = None):
99bea633   tangwang   add logs
71
72
          # 生成唯一请求ID;如果外部未提供,则自动生成
          # 如果无法获取到 uid,则使用 "-1" 作为占位,用于日志关联
16c42787   tangwang   feat: implement r...
73
          self.reqid = reqid or str(uuid.uuid4())[:8]
99bea633   tangwang   add logs
74
          self.uid = uid or "-1"
16c42787   tangwang   feat: implement r...
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
  
          # 查询分析结果
          self.query_analysis = QueryAnalysisResult()
  
          # 各检索阶段中间结果
          self.intermediate_results = {
              'parsed_query': None,
              'query_node': None,
              'es_query': {},
              'es_response': {},
              'processed_hits': [],
              'raw_hits': []
          }
  
          # 性能指标
          self.performance_metrics = PerformanceMetrics()
  
          # 元数据
          self.metadata = {
              'search_params': {},  # size, from_, filters等
345d960b   tangwang   1. 删除全局 enable_tr...
95
              'feature_flags': {},  # translation_enabled (由tenant_config控制), enable_embedding等
16c42787   tangwang   feat: implement r...
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
              'config_info': {},   # 索引配置、字段映射等
              'error_info': None,
              'warnings': []
          }
  
          # 日志记录器引用(延迟初始化)
          self._logger = None
  
      @property
      def logger(self):
          """获取日志记录器"""
          if self._logger is None:
              from utils.logger import get_logger
              self._logger = get_logger("request_context")
          return self._logger
  
      def start_stage(self, stage: RequestContextStage) -> float:
          """
          开始一个阶段的计时
  
          Args:
              stage: 阶段枚举
  
          Returns:
              开始时间戳
          """
          start_time = time.time()
          self.performance_metrics.stage_start_times[stage.value] = start_time
99bea633   tangwang   add logs
124
125
126
127
          self.logger.debug(
              f"Start stage | {stage.value}",
              extra={'reqid': self.reqid, 'uid': self.uid}
          )
16c42787   tangwang   feat: implement r...
128
129
130
131
132
133
134
135
136
137
138
139
140
          return start_time
  
      def end_stage(self, stage: RequestContextStage) -> float:
          """
          结束一个阶段的计时
  
          Args:
              stage: 阶段枚举
  
          Returns:
              阶段耗时(毫秒)
          """
          if stage.value not in self.performance_metrics.stage_start_times:
99bea633   tangwang   add logs
141
142
143
144
              self.logger.warning(
                  f"Stage not started | {stage.value}",
                  extra={'reqid': self.reqid, 'uid': self.uid}
              )
16c42787   tangwang   feat: implement r...
145
146
147
              return 0.0
  
          start_time = self.performance_metrics.stage_start_times[stage.value]
8ae95af0   tangwang   1. Stage Timings:...
148
149
          end_time = time.time()
          duration_ms = (end_time - start_time) * 1000
16c42787   tangwang   feat: implement r...
150
          self.performance_metrics.stage_timings[stage.value] = duration_ms
8ae95af0   tangwang   1. Stage Timings:...
151
152
153
154
          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),
          }
16c42787   tangwang   feat: implement r...
155
156
  
          self.logger.debug(
99bea633   tangwang   add logs
157
              f"End stage | {stage.value} | duration: {duration_ms:.2f}ms",
16c42787   tangwang   feat: implement r...
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
              extra={'reqid': self.reqid, 'uid': self.uid}
          )
          return duration_ms
  
      def get_stage_duration(self, stage: RequestContextStage) -> float:
          """
          获取指定阶段的耗时
  
          Args:
              stage: 阶段枚举
  
          Returns:
              阶段耗时(毫秒),如果未计时则返回0
          """
          return self.performance_metrics.stage_timings.get(stage.value, 0.0)
  
      def store_query_analysis(self, **kwargs) -> None:
          """
          存储查询分析结果
  
          Args:
              **kwargs: 查询分析相关的字段
          """
          for key, value in kwargs.items():
              if hasattr(self.query_analysis, key):
                  setattr(self.query_analysis, key, value)
              else:
                  self.logger.warning(
99bea633   tangwang   add logs
186
                      f"Unknown query analysis field | {key}",
16c42787   tangwang   feat: implement r...
187
188
189
190
191
192
193
194
195
196
197
198
                      extra={'reqid': self.reqid, 'uid': self.uid}
                  )
  
      def store_intermediate_result(self, key: str, value: Any) -> None:
          """
          存储中间结果
  
          Args:
              key: 结果键名
              value: 结果值
          """
          self.intermediate_results[key] = value
99bea633   tangwang   add logs
199
200
201
202
          self.logger.debug(
              f"Store intermediate result | {key}",
              extra={'reqid': self.reqid, 'uid': self.uid}
          )
16c42787   tangwang   feat: implement r...
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
  
      def get_intermediate_result(self, key: str, default: Any = None) -> Any:
          """
          获取中间结果
  
          Args:
              key: 结果键名
              default: 默认值
  
          Returns:
              中间结果值
          """
          return self.intermediate_results.get(key, default)
  
      def add_warning(self, warning: str) -> None:
          """
          添加警告信息
  
          Args:
              warning: 警告信息
          """
          self.metadata['warnings'].append(warning)
          self.logger.warning(warning, extra={'reqid': self.reqid, 'uid': self.uid})
  
      def set_error(self, error: Exception) -> None:
          """
          设置错误信息
  
          Args:
              error: 异常对象
          """
          self.metadata['error_info'] = {
              'type': type(error).__name__,
              'message': str(error),
              'details': {}
          }
          self.logger.error(
99bea633   tangwang   add logs
240
              f"Set error info | {type(error).__name__}: {str(error)}",
16c42787   tangwang   feat: implement r...
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
              extra={'reqid': self.reqid, 'uid': self.uid}
          )
  
      def has_error(self) -> bool:
          """检查是否有错误"""
          return self.metadata['error_info'] is not None
  
      def calculate_stage_percentages(self) -> Dict[str, float]:
          """
          计算各阶段耗时占总耗时的百分比
  
          Returns:
              各阶段耗时占比字典
          """
          total = self.performance_metrics.total_duration
          if total <= 0:
              return {}
  
          percentages = {}
          for stage, duration in self.performance_metrics.stage_timings.items():
              percentages[stage] = round((duration / total) * 100, 2)
  
          return percentages
  
      def get_summary(self) -> Dict[str, Any]:
          """
          获取完整的上下文摘要
  
          Returns:
              包含所有关键信息的字典
          """
          return {
              'request_info': {
                  'reqid': self.reqid,
                  'uid': self.uid,
                  'has_error': self.has_error(),
                  'warnings_count': len(self.metadata['warnings'])
              },
              'query_analysis': {
                  'original_query': self.query_analysis.original_query,
3a5fda00   tangwang   1. ES字段 skus的 ima...
281
                  'query_normalized': self.query_analysis.query_normalized,
16c42787   tangwang   feat: implement r...
282
283
284
                  'rewritten_query': self.query_analysis.rewritten_query,
                  'detected_language': self.query_analysis.detected_language,
                  'domain': self.query_analysis.domain,
16c42787   tangwang   feat: implement r...
285
286
287
288
289
290
291
                  'is_simple_query': self.query_analysis.is_simple_query
              },
              'performance': {
                  'total_duration_ms': round(self.performance_metrics.total_duration, 2),
                  'stage_timings_ms': {
                      k: round(v, 2) for k, v in self.performance_metrics.stage_timings.items()
                  },
8ae95af0   tangwang   1. Stage Timings:...
292
293
294
295
296
297
                  '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()
                  },
16c42787   tangwang   feat: implement r...
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
                  'stage_percentages': self.calculate_stage_percentages()
              },
              'results': {
                  'total_hits': len(self.intermediate_results.get('processed_hits', [])),
                  'has_es_response': bool(self.intermediate_results.get('es_response')),
                  'es_query_size': len(str(self.intermediate_results.get('es_query', {})))
              },
              'metadata': {
                  'feature_flags': self.metadata['feature_flags'],
                  'search_params': self.metadata['search_params'],
                  'config_info': self.metadata['config_info']
              }
          }
  
      def log_performance_summary(self) -> None:
          """记录完整的性能摘要日志"""
          summary = self.get_summary()
  
          # 构建详细的日志消息
          msg_parts = [
99bea633   tangwang   add logs
318
319
              f"Search request performance summary | reqid: {self.reqid}",
              f"Total duration: {summary['performance']['total_duration_ms']:.2f}ms"
16c42787   tangwang   feat: implement r...
320
321
322
323
          ]
  
          # 添加各阶段耗时
          if summary['performance']['stage_timings_ms']:
99bea633   tangwang   add logs
324
              msg_parts.append("Stage durations:")
8ae95af0   tangwang   1. Stage Timings:...
325
              bounds_map = summary['performance'].get('stage_time_bounds_ms') or {}
16c42787   tangwang   feat: implement r...
326
327
              for stage, duration in summary['performance']['stage_timings_ms'].items():
                  percentage = summary['performance']['stage_percentages'].get(stage, 0)
8ae95af0   tangwang   1. Stage Timings:...
328
329
330
331
332
333
334
335
                  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}%)")
16c42787   tangwang   feat: implement r...
336
337
338
339
  
          # 添加查询信息
          if summary['query_analysis']['original_query']:
              msg_parts.append(
99bea633   tangwang   add logs
340
341
                  "Query: "
                  f"'{summary['query_analysis']['original_query']}' "
16c42787   tangwang   feat: implement r...
342
343
344
345
346
347
                  f"-> '{summary['query_analysis']['rewritten_query']}' "
                  f"({summary['query_analysis']['detected_language']})"
              )
  
          # 添加结果统计
          msg_parts.append(
99bea633   tangwang   add logs
348
349
              f"Results: {summary['results']['total_hits']} hits "
              f"ES query size: {summary['results']['es_query_size']} chars"
16c42787   tangwang   feat: implement r...
350
351
352
353
354
          )
  
          # 添加错误信息(如果有)
          if summary['request_info']['has_error']:
              error_info = self.metadata['error_info']
99bea633   tangwang   add logs
355
              msg_parts.append(f"Error: {error_info['type']}: {error_info['message']}")
16c42787   tangwang   feat: implement r...
356
357
358
  
          # 添加警告信息(如果有)
          if summary['request_info']['warnings_count'] > 0:
99bea633   tangwang   add logs
359
              msg_parts.append(f"Warnings: {summary['request_info']['warnings_count']}")
16c42787   tangwang   feat: implement r...
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
  
          log_message = " | ".join(msg_parts)
  
          if self.has_error():
              self.logger.error(log_message, extra={'extra_data': summary, 'reqid': self.reqid, 'uid': self.uid})
          elif summary['request_info']['warnings_count'] > 0:
              self.logger.warning(log_message, extra={'extra_data': summary, 'reqid': self.reqid, 'uid': self.uid})
          else:
              self.logger.info(log_message, extra={'extra_data': summary, 'reqid': self.reqid, 'uid': self.uid})
  
      def __enter__(self):
          """上下文管理器入口"""
          self.start_stage(RequestContextStage.TOTAL)
          return self
  
      def __exit__(self, exc_type, exc_val, exc_tb):
          """上下文管理器出口"""
          # 结束总计时
          self.end_stage(RequestContextStage.TOTAL)
          self.performance_metrics.total_duration = self.get_stage_duration(RequestContextStage.TOTAL)
  
          # 记录性能摘要
          self.log_performance_summary()
  
          # 如果有异常,记录错误信息
          if exc_type and exc_val:
              self.set_error(exc_val)
  
  
  # 便利函数
  def create_request_context(reqid: str = None, uid: str = None) -> RequestContext:
      """创建新的请求上下文"""
      return RequestContext(reqid, uid)
  
  
  def get_current_request_context() -> Optional[RequestContext]:
      """获取当前线程的请求上下文(如果已设置)"""
      return getattr(threading.current_thread(), 'request_context', None)
  
  
  def set_current_request_context(context: RequestContext) -> None:
      """设置当前线程的请求上下文"""
      threading.current_thread().request_context = context
4650fcec   tangwang   日志优化、日志串联(uid rqid)
403
404
      _, _, tokens = bind_request_log_context(context.reqid, context.uid)
      threading.current_thread().request_log_tokens = tokens
16c42787   tangwang   feat: implement r...
405
406
407
408
  
  
  def clear_current_request_context() -> None:
      """清除当前线程的请求上下文"""
4650fcec   tangwang   日志优化、日志串联(uid rqid)
409
410
411
412
      tokens = getattr(threading.current_thread(), 'request_log_tokens', None)
      if tokens is not None:
          reset_request_log_context(tokens)
          delattr(threading.current_thread(), 'request_log_tokens')
16c42787   tangwang   feat: implement r...
413
414
      if hasattr(threading.current_thread(), 'request_context'):
          delattr(threading.current_thread(), 'request_context')