metrics.py 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398
  1. import functools
  2. import logging
  3. import time
  4. from enum import Enum
  5. from typing import Any, Callable, Optional, Union
  6. class RequestStatus(Enum):
  7. """Status of a generation request through its lifecycle."""
  8. PENDING = "pending"
  9. PREFILLING = "prefilling"
  10. PREFILLING_SPLIT = "prefilling_split"
  11. SPLIT_PENDING_REMAINDER = "split_pending_remainder"
  12. DECODING = "decoding"
  13. FINISHED = "finished"
  14. FAILED = "failed"
  15. try:
  16. from opentelemetry import metrics
  17. from opentelemetry.trace import Status, StatusCode, get_tracer
  18. _has_opentelemetry = True
  19. except ImportError:
  20. _has_opentelemetry = False
  21. def attach_tracer(tracer_name_template=None):
  22. """
  23. Decorator that attaches a tracer to a class.
  24. This decorator should be applied to classes that need OpenTelemetry tracing.
  25. It adds a tracer attribute to the class instance that can be used by the traced decorator.
  26. Args:
  27. tracer_name_template: Optional template string for the tracer name.
  28. If provided, it should contain {module} which will be replaced with the class's full module path
  29. and {class_name} for the class name.
  30. If None, a default naming scheme will be used where:
  31. - If the module already starts with "transformers.", it will use that directly
  32. - Otherwise, it will prepend "transformers." to the module name
  33. Returns:
  34. Class decorator function
  35. """
  36. if not _has_opentelemetry:
  37. return lambda cls: cls
  38. def decorator(cls):
  39. original_init = cls.__init__
  40. @functools.wraps(original_init)
  41. def init_with_tracer(self, *args, **kwargs):
  42. original_init(self, *args, **kwargs)
  43. module_name = cls.__module__
  44. class_name = cls.__qualname__
  45. if tracer_name_template is None:
  46. if module_name.startswith("transformers."):
  47. tracer_name = f"{module_name}.{class_name}"
  48. else:
  49. tracer_name = f"transformers.{module_name}.{class_name}"
  50. else:
  51. tracer_name = tracer_name_template.format(module=module_name, class_name=class_name)
  52. self.tracer = get_tracer(tracer_name)
  53. cls.__init__ = init_with_tracer
  54. return cls
  55. return decorator
  56. def traced(
  57. func=None,
  58. *,
  59. span_name=None,
  60. standalone=False,
  61. additional_attributes: Optional[list[tuple[str, str, Union[Any, Callable[[Any], Any]]]]] = None,
  62. ):
  63. """
  64. Decorator to trace function calls with OpenTelemetry.
  65. Can be used as @traced or @traced(span_name="custom_name")
  66. Args:
  67. func: The function to trace
  68. span_name: Optional custom name for the span (defaults to function name)
  69. standalone: If True, creates a parentless span
  70. additional_attributes: Optional list of additional attributes to set on the span.
  71. Each item is a tuple of (instance_attribute_name, span_attribute_key, value_or_transform_function)
  72. where:
  73. - instance_attribute_name: Name of the attribute to get from the class instance
  74. - span_attribute_key: Key to use when setting the attribute on the span
  75. - value_or_transform_function: Either a raw value to use directly, or a function to transform
  76. the attribute value before setting it on the span
  77. Returns:
  78. Decorated function with tracing
  79. """
  80. def decorator(func):
  81. if not _has_opentelemetry:
  82. return func
  83. @functools.wraps(func)
  84. def wrapper(*args, **kwargs):
  85. instance = args[0] if args and (hasattr(func, "__self__") and func.__self__ is not None) else None
  86. is_method = instance is not None
  87. if is_method and hasattr(instance, "tracer"):
  88. tracer = instance.tracer
  89. else:
  90. tracer = get_tracer(f"transformers.{func.__module__}.{func.__name__}")
  91. name = span_name or func.__name__
  92. span_fn = tracer.start_span if standalone else tracer.start_as_current_span
  93. with span_fn(name) as span:
  94. span.set_attribute("function.name", func.__name__)
  95. span.set_attribute("function.module", func.__module__)
  96. span.set_attribute("function.is_method", is_method)
  97. if args:
  98. for i, arg in enumerate(args):
  99. if isinstance(arg, (str, int, float, bool)) or arg is None:
  100. span.set_attribute(f"args.{i}", str(arg))
  101. else:
  102. span.set_attribute(f"args.{i}", str(type(arg)))
  103. if kwargs:
  104. for key, value in kwargs.items():
  105. if isinstance(value, (str, int, float, bool)) or value is None:
  106. span.set_attribute(f"kwargs.{key}", str(value))
  107. else:
  108. span.set_attribute(f"kwargs.{key}", str(type(value)))
  109. if additional_attributes and is_method:
  110. for attr_config in additional_attributes:
  111. instance_attribute_name, span_attribute_key, value_or_transform_function = attr_config
  112. if hasattr(instance, instance_attribute_name):
  113. attribute_value = getattr(instance, instance_attribute_name)
  114. if callable(value_or_transform_function):
  115. transformed_value = value_or_transform_function(attribute_value)
  116. else:
  117. transformed_value = value_or_transform_function
  118. span.set_attribute(span_attribute_key, transformed_value)
  119. try:
  120. result = func(*args, **kwargs)
  121. return result
  122. except Exception as e:
  123. span.set_status(Status(StatusCode.ERROR))
  124. span.record_exception(e)
  125. raise
  126. return wrapper
  127. if func is None:
  128. return decorator
  129. return decorator(func)
  130. logger = logging.getLogger(__name__)
  131. @attach_tracer()
  132. class ContinuousBatchProcessorMetrics:
  133. """Metrics collection for ContinuousBatchProcessor."""
  134. def __init__(self, max_batch_tokens: int):
  135. """Initialize metrics for continuous batch processor.
  136. Args:
  137. max_batch_tokens: Maximum number of tokens in a batch
  138. """
  139. self.max_batch_tokens = max_batch_tokens
  140. self._setup_metrics()
  141. def _setup_metrics(self):
  142. """Initialize OpenTelemetry metrics and tracing if the library is available."""
  143. if not _has_opentelemetry:
  144. logger.info("OpenTelemetry is not installed. Metrics and tracing will not be recorded.")
  145. return
  146. self.meter = metrics.get_meter("transformers.generation.continuous_batch_processor")
  147. # Define appropriate buckets for TTFT (typically ranges from ~50ms to several seconds)
  148. ttft_buckets = [10, 25, 50, 75, 100, 150, 200, 300, 500, 750, 1000, 2000, 5000, 10000]
  149. self.ttft_histogram = self.meter.create_histogram(
  150. name="ttft_milliseconds",
  151. description="Time to first token in milliseconds",
  152. unit="ms",
  153. explicit_bucket_boundaries_advisory=ttft_buckets,
  154. )
  155. self.active_requests_gauge = self.meter.create_gauge(
  156. name="active_requests_count",
  157. description="Number of active requests currently being processed",
  158. unit="requests",
  159. )
  160. self.waiting_requests_gauge = self.meter.create_gauge(
  161. name="waiting_requests_count",
  162. description="Number of requests waiting to be processed",
  163. unit="requests",
  164. )
  165. # Define appropriate buckets for request latency (similar to TTFT but with higher upper bounds)
  166. latency_buckets = [50, 100, 250, 500, 1000, 2000, 5000, 10000, 20000, 30000, 60000]
  167. self.request_latency_histogram = self.meter.create_histogram(
  168. name="request_latency_milliseconds",
  169. description="End-to-end latency for completed requests in milliseconds",
  170. unit="ms",
  171. explicit_bucket_boundaries_advisory=latency_buckets,
  172. )
  173. self.decode_prefill_ratio_gauge = self.meter.create_gauge(
  174. name="decode_prefill_ratio",
  175. description="Ratio of decode tokens to prefill tokens in a batch",
  176. unit="ratio",
  177. )
  178. self.prefill_tokens_counter = self.meter.create_counter(
  179. name="prefill_tokens_processed",
  180. description="Number of prefill tokens processed",
  181. unit="tokens",
  182. )
  183. self.decode_tokens_counter = self.meter.create_counter(
  184. name="decode_tokens_processed",
  185. description="Number of decode tokens processed",
  186. unit="tokens",
  187. )
  188. # Define appropriate buckets for batch fill percentage (0-100%)
  189. batch_fill_buckets = [5, 10, 20, 30, 40, 50, 60, 70, 80, 90, 95, 98, 100]
  190. self.batch_fill_percentage_histogram = self.meter.create_histogram(
  191. name="batch_fill_percentage",
  192. description="Percentage of max_batch_tokens utilized in each batch",
  193. unit="percent",
  194. explicit_bucket_boundaries_advisory=batch_fill_buckets,
  195. )
  196. self.kv_cache_free_memory_gauge = self.meter.create_gauge(
  197. name="kv_cache_free_memory_bytes",
  198. description="Free memory of the PagedAttentionCache in bytes",
  199. unit="bytes",
  200. )
  201. self.kv_cache_memory_gauge = self.meter.create_gauge(
  202. name="kv_cache_memory_bytes",
  203. description="Memory usage of the PagedAttentionCache in bytes",
  204. unit="bytes",
  205. )
  206. @traced
  207. def record_ttft_metric(self, created_time: float, request_id: str) -> None:
  208. """Record Time to First Token (TTFT).
  209. Args:
  210. created_time: The time the request was created
  211. request_id: The ID of the request
  212. """
  213. if not _has_opentelemetry:
  214. return
  215. ttft_ms = (time.time() - created_time) * 1000.0
  216. try:
  217. self.ttft_histogram.record(ttft_ms)
  218. logger.debug(f"Recorded TTFT for request {request_id}: {ttft_ms:.2f}ms")
  219. except Exception as e:
  220. logger.warning(f"Failed to record TTFT metric: {e}")
  221. @traced
  222. def record_batch_metrics(self, requests_in_batch: list) -> None:
  223. """Record metrics about the batch composition including decode/prefill ratio and batch fill percentage.
  224. Args:
  225. requests_in_batch: List of request states in the current batch
  226. """
  227. if not _has_opentelemetry or not requests_in_batch:
  228. return
  229. decode_tokens = 0
  230. prefill_tokens = 0
  231. for state in requests_in_batch:
  232. if state.status == RequestStatus.DECODING:
  233. decode_tokens += 1
  234. elif state.status in [RequestStatus.PREFILLING, RequestStatus.PREFILLING_SPLIT]:
  235. prefill_tokens += len(state.prompt_ids)
  236. total_batch_tokens = decode_tokens + prefill_tokens
  237. try:
  238. if prefill_tokens > 0:
  239. self.prefill_tokens_counter.add(prefill_tokens)
  240. if decode_tokens > 0:
  241. self.decode_tokens_counter.add(decode_tokens)
  242. if prefill_tokens > 0:
  243. ratio = decode_tokens / prefill_tokens
  244. self.decode_prefill_ratio_gauge.set(ratio)
  245. fill_percentage = (total_batch_tokens / self.max_batch_tokens) * 100.0
  246. self.batch_fill_percentage_histogram.record(fill_percentage)
  247. logger.debug(
  248. f"Batch metrics: {decode_tokens} decode tokens, {prefill_tokens} prefill tokens, "
  249. f"batch fill: {fill_percentage:.2f}% ({total_batch_tokens}/{self.max_batch_tokens})"
  250. )
  251. except Exception as e:
  252. logger.warning(f"Failed to record batch metrics: {e}")
  253. @traced
  254. def record_kv_cache_memory_metrics(self, cache) -> None:
  255. """Record memory usage of the PagedAttentionCache without GPU synchronization.
  256. This calculates the theoretical memory usage based on cache configuration
  257. and the number of blocks currently in use.
  258. Args:
  259. cache: The PagedAttentionCache object to measure
  260. """
  261. if not _has_opentelemetry:
  262. return
  263. try:
  264. # Retrieve the memory footprint of the cache
  265. page_size = cache.head_dim * cache.num_key_value_heads
  266. page_mem_in_bytes = page_size * cache.dtype.itemsize
  267. # When a block is allocated, it is for both K and V, so we multiply by 2
  268. # It's also allocated across all cache tensors, so we multiply by the nb of tensors: len(cache.key_cache)
  269. block_mem_in_bytes = 2 * len(cache.key_cache) * cache.block_size * page_mem_in_bytes
  270. # Retrieve the number of used and free blocks
  271. free_blocks = cache.get_num_free_blocks()
  272. used_blocks = cache.num_blocks - free_blocks
  273. # Convert that into used and free memory in bytes
  274. used_memory_bytes = used_blocks * block_mem_in_bytes
  275. free_memory_bytes = free_blocks * block_mem_in_bytes
  276. # Update the telemetry gauges and add a message in the logs
  277. self.kv_cache_memory_gauge.set(used_memory_bytes)
  278. self.kv_cache_free_memory_gauge.set(free_memory_bytes)
  279. logger.debug(
  280. f"KV Cache memory: {used_memory_bytes / (1024 * 1024):.2f}MB, "
  281. f"Used blocks: {used_blocks}/{cache.num_blocks} "
  282. f"({used_blocks / cache.num_blocks * 100:.1f}%)"
  283. )
  284. except Exception as e:
  285. logger.warning(f"Failed to record KV cache memory metrics: {e}")
  286. @traced
  287. def record_queue_metrics(self, active_requests: int, waiting_requests: int) -> None:
  288. """Record metrics about active and waiting requests.
  289. Args:
  290. active_requests: Number of active requests
  291. waiting_requests: Number of waiting requests
  292. """
  293. if not _has_opentelemetry:
  294. return
  295. try:
  296. self.active_requests_gauge.set(active_requests)
  297. self.waiting_requests_gauge.set(waiting_requests)
  298. logger.debug(f"Queue metrics: {active_requests} active requests, {waiting_requests} waiting requests")
  299. except Exception as e:
  300. logger.warning(f"Failed to record queue metrics: {e}")
  301. @traced
  302. def record_request_completion(self, created_time: float, request_id: str) -> None:
  303. """Record metrics about a completed request.
  304. Args:
  305. created_time: The time the request was created
  306. request_id: The ID of the request
  307. """
  308. if not _has_opentelemetry:
  309. return
  310. latency_ms = (time.time() - created_time) * 1000.0
  311. try:
  312. self.request_latency_histogram.record(latency_ms)
  313. logger.debug(f"Recorded request completion for {request_id}: {latency_ms:.2f}ms")
  314. except Exception as e:
  315. logger.warning(f"Failed to record request completion metric: {e}")