async_aphrodite.py 50 KB

12345678910111213141516171819202122232425262728293031323334353637383940414243444546474849505152535455565758596061626364656667686970717273747576777879808182838485868788899091929394959697989910010110210310410510610710810911011111211311411511611711811912012112212312412512612712812913013113213313413513613713813914014114214314414514614714814915015115215315415515615715815916016116216316416516616716816917017117217317417517617717817918018118218318418518618718818919019119219319419519619719819920020120220320420520620720820921021121221321421521621721821922022122222322422522622722822923023123223323423523623723823924024124224324424524624724824925025125225325425525625725825926026126226326426526626726826927027127227327427527627727827928028128228328428528628728828929029129229329429529629729829930030130230330430530630730830931031131231331431531631731831932032132232332432532632732832933033133233333433533633733833934034134234334434534634734834935035135235335435535635735835936036136236336436536636736836937037137237337437537637737837938038138238338438538638738838939039139239339439539639739839940040140240340440540640740840941041141241341441541641741841942042142242342442542642742842943043143243343443543643743843944044144244344444544644744844945045145245345445545645745845946046146246346446546646746846947047147247347447547647747847948048148248348448548648748848949049149249349449549649749849950050150250350450550650750850951051151251351451551651751851952052152252352452552652752852953053153253353453553653753853954054154254354454554654754854955055155255355455555655755855956056156256356456556656756856957057157257357457557657757857958058158258358458558658758858959059159259359459559659759859960060160260360460560660760860961061161261361461561661761861962062162262362462562662762862963063163263363463563663763863964064164264364464564664764864965065165265365465565665765865966066166266366466566666766866967067167267367467567667767867968068168268368468568668768868969069169269369469569669769869970070170270370470570670770870971071171271371471571671771871972072172272372472572672772872973073173273373473573673773873974074174274374474574674774874975075175275375475575675775875976076176276376476576676776876977077177277377477577677777877978078178278378478578678778878979079179279379479579679779879980080180280380480580680780880981081181281381481581681781881982082182282382482582682782882983083183283383483583683783883984084184284384484584684784884985085185285385485585685785885986086186286386486586686786886987087187287387487587687787887988088188288388488588688788888989089189289389489589689789889990090190290390490590690790890991091191291391491591691791891992092192292392492592692792892993093193293393493593693793893994094194294394494594694794894995095195295395495595695795895996096196296396496596696796896997097197297397497597697797897998098198298398498598698798898999099199299399499599699799899910001001100210031004100510061007100810091010101110121013101410151016101710181019102010211022102310241025102610271028102910301031103210331034103510361037103810391040104110421043104410451046104710481049105010511052105310541055105610571058105910601061106210631064106510661067106810691070107110721073107410751076107710781079108010811082108310841085108610871088108910901091109210931094109510961097109810991100110111021103110411051106110711081109111011111112111311141115111611171118111911201121112211231124112511261127112811291130113111321133113411351136113711381139114011411142114311441145114611471148114911501151115211531154115511561157115811591160116111621163116411651166116711681169117011711172117311741175117611771178117911801181118211831184118511861187118811891190119111921193119411951196119711981199120012011202120312041205120612071208
  1. import asyncio
  2. import time
  3. from dataclasses import dataclass
  4. from functools import partial
  5. from typing import (Any, AsyncGenerator, Callable, Dict, Iterable, List,
  6. Optional, Set, Tuple, Type, Union)
  7. import torch
  8. from loguru import logger
  9. from transformers import PreTrainedTokenizer
  10. from typing_extensions import assert_never
  11. import aphrodite.common.envs as envs
  12. from aphrodite.common.config import (DecodingConfig, EngineConfig, LoRAConfig,
  13. ModelConfig, ParallelConfig,
  14. SchedulerConfig)
  15. from aphrodite.common.outputs import EmbeddingRequestOutput, RequestOutput
  16. from aphrodite.common.pooling_params import PoolingParams
  17. from aphrodite.common.sampling_params import SamplingParams
  18. from aphrodite.common.sequence import (ExecuteModelRequest, SamplerOutput,
  19. SequenceGroupMetadata)
  20. from aphrodite.engine.aphrodite_engine import (AphroditeEngine,
  21. DecoderPromptComponents,
  22. PromptComponents)
  23. from aphrodite.engine.args_tools import AsyncEngineArgs
  24. from aphrodite.engine.async_timeout import asyncio_timeout
  25. from aphrodite.engine.metrics_types import StatLoggerBase
  26. from aphrodite.executor.executor_base import ExecutorAsyncBase
  27. from aphrodite.executor.ray_utils import initialize_ray_cluster, ray
  28. from aphrodite.inputs import (EncoderDecoderLLMInputs, LLMInputs, PromptInputs,
  29. SingletonPromptInputs)
  30. from aphrodite.inputs.parse import is_explicit_encoder_decoder_prompt
  31. from aphrodite.lora.request import LoRARequest
  32. from aphrodite.processing.scheduler import SchedulerOutputs
  33. from aphrodite.prompt_adapter.request import PromptAdapterRequest
  34. ENGINE_ITERATION_TIMEOUT_S = envs.APHRODITE_ENGINE_ITERATION_TIMEOUT_S
  35. class AsyncEngineDeadError(RuntimeError):
  36. pass
  37. def _log_task_completion(task: asyncio.Task,
  38. error_callback: Callable[[Exception], None]) -> None:
  39. """This function is only intended for the `engine.run_engine_loop()` task.
  40. In particular, that task runs a `while True` loop that can only exit if
  41. there is an exception.
  42. """
  43. exception = None
  44. try:
  45. return_value = task.result()
  46. raise AssertionError(
  47. f"The engine background task should never finish without an "
  48. f"exception. {return_value}")
  49. except asyncio.exceptions.CancelledError:
  50. # We assume that if the task is cancelled, we are gracefully shutting
  51. # down. This should only happen on program exit.
  52. logger.info("Engine is gracefully shutting down.")
  53. except Exception as e:
  54. exception = e
  55. logger.error("Engine background task failed", exc_info=e)
  56. error_callback(exception)
  57. raise AsyncEngineDeadError(
  58. "Task finished unexpectedly. This should never happen! "
  59. "Please open an issue on Github. See stack trace above for the "
  60. "actual cause.") from e
  61. STOP_ITERATION = Exception() # Sentinel
  62. class AsyncStream:
  63. """A stream of RequestOutputs or EmbeddingRequestOutputs for a request
  64. that can be iterated over asynchronously via an async generator."""
  65. def __init__(self, request_id: str, cancel: Callable[[str], None]) -> None:
  66. self.request_id = request_id
  67. self._cancel = cancel
  68. self._queue: asyncio.Queue = asyncio.Queue()
  69. self._finished = False
  70. def put(self, item: Union[RequestOutput, EmbeddingRequestOutput,
  71. Exception]) -> None:
  72. if not self._finished:
  73. self._queue.put_nowait(item)
  74. def finish(
  75. self,
  76. exception: Optional[Union[BaseException, Type[BaseException]]] = None,
  77. ) -> None:
  78. if not self._finished:
  79. self._finished = True
  80. self._queue.put_nowait(
  81. exception if self._is_raisable(exception) else STOP_ITERATION)
  82. @property
  83. def finished(self) -> bool:
  84. return self._finished
  85. async def generator(
  86. self
  87. ) -> AsyncGenerator[Union[RequestOutput, EmbeddingRequestOutput], None]:
  88. try:
  89. while True:
  90. result = await self._queue.get()
  91. if self._is_raisable(result):
  92. if result == STOP_ITERATION:
  93. return
  94. raise result
  95. yield result
  96. except GeneratorExit:
  97. self._cancel(self.request_id)
  98. raise asyncio.CancelledError from None
  99. @staticmethod
  100. def _is_raisable(value: Any):
  101. return isinstance(value, BaseException) or \
  102. (isinstance(value, type) and \
  103. issubclass(value, BaseException))
  104. class RequestTracker:
  105. """Synchronous abstraction for tracking requests."""
  106. def __init__(self) -> None:
  107. self._request_streams: Dict[str, AsyncStream] = {}
  108. self._aborted_requests: asyncio.Queue[str] = asyncio.Queue()
  109. self._new_requests: asyncio.Queue[Tuple[AsyncStream,
  110. dict]] = asyncio.Queue()
  111. self.new_requests_event = asyncio.Event()
  112. def __contains__(self, item):
  113. return item in self._request_streams
  114. def __len__(self) -> int:
  115. return len(self._request_streams)
  116. def propagate_exception(self,
  117. exc: Exception,
  118. request_id: Optional[str] = None) -> None:
  119. """Propagate an exception to request streams
  120. (all if request_id is None)."""
  121. if request_id is not None:
  122. self.abort_request(request_id, exception=exc)
  123. else:
  124. # NB: tuple() used here because self.abort_request pops the stream
  125. # out of self._request_streams, so we can't iterate on it directly
  126. for rid in tuple(self._request_streams.keys()):
  127. self.abort_request(rid, exception=exc)
  128. def process_request_output(self,
  129. request_output: Union[RequestOutput,
  130. EmbeddingRequestOutput],
  131. *,
  132. verbose: bool = False) -> None:
  133. """Process a request output from the engine."""
  134. request_id = request_output.request_id
  135. finished = request_output.finished
  136. if finished:
  137. stream = self._request_streams.pop(request_id, None)
  138. else:
  139. stream = self._request_streams.get(request_id)
  140. # Guard against a KeyError which can occur if the request was aborted
  141. # while the output was generated
  142. if stream is not None:
  143. stream.put(request_output)
  144. if finished:
  145. stream.finish()
  146. if verbose and finished:
  147. logger.info(f"Finished request {request_id}.")
  148. def process_exception(self,
  149. request_id: str,
  150. exception: BaseException,
  151. *,
  152. verbose: bool = False) -> None:
  153. """Propagate an exception from the engine."""
  154. if verbose:
  155. logger.info(f"Finished request {request_id}.")
  156. self.abort_request(request_id, exception=exception)
  157. def add_request(self,
  158. request_id: str,
  159. *,
  160. verbose: bool = False,
  161. **engine_add_request_kwargs) -> AsyncStream:
  162. """Add a request to be sent to the engine on the next background
  163. loop iteration."""
  164. if request_id in self._request_streams:
  165. raise KeyError(f"Request {request_id} already exists.")
  166. abort_request = partial(self.abort_request, verbose=verbose)
  167. stream = AsyncStream(request_id, abort_request)
  168. self._new_requests.put_nowait((stream, {
  169. "request_id": request_id,
  170. **engine_add_request_kwargs
  171. }))
  172. self.new_requests_event.set()
  173. if verbose:
  174. logger.info(f"Added request {request_id}.")
  175. return stream
  176. def abort_request(self,
  177. request_id: str,
  178. *,
  179. exception: Optional[Union[BaseException,
  180. Type[BaseException]]] = None,
  181. verbose: bool = False) -> None:
  182. """Abort a request during next background loop iteration."""
  183. if verbose:
  184. logger.info(f"Aborted request {request_id}.")
  185. self._aborted_requests.put_nowait(request_id)
  186. stream = self._request_streams.pop(request_id, None)
  187. if stream is not None:
  188. stream.finish(exception=exception)
  189. def get_new_and_aborted_requests(self) -> Tuple[List[Dict], Set[str]]:
  190. """Get the new requests and finished requests to be
  191. sent to the engine."""
  192. new_requests: List[Dict] = []
  193. finished_requests: Set[str] = set()
  194. while not self._aborted_requests.empty():
  195. request_id = self._aborted_requests.get_nowait()
  196. finished_requests.add(request_id)
  197. while not self._new_requests.empty():
  198. stream, new_request = self._new_requests.get_nowait()
  199. request_id = stream.request_id
  200. if request_id in finished_requests:
  201. # The request has already been aborted.
  202. stream.finish(asyncio.CancelledError)
  203. finished_requests.discard(request_id)
  204. else:
  205. self._request_streams[request_id] = stream
  206. new_requests.append(new_request)
  207. return new_requests, finished_requests
  208. async def wait_for_new_requests(self):
  209. if not self.has_new_requests():
  210. await self.new_requests_event.wait()
  211. self.new_requests_event.clear()
  212. def has_new_requests(self):
  213. return not self._new_requests.empty()
  214. @dataclass
  215. class SchedulerOutputState:
  216. """Caches the scheduler outputs for a virtual engine. Used for Multi-Step"""
  217. last_output: Optional[SamplerOutput] = None
  218. seq_group_metadata_list: Optional[List[SequenceGroupMetadata]] = None
  219. scheduler_outputs: Optional[SchedulerOutputs] = None
  220. class _AsyncAphrodite(AphroditeEngine):
  221. """Extension of AphroditeEngine to add async methods."""
  222. def __init__(self, *args, **kwargs):
  223. super().__init__(*args, **kwargs)
  224. pipeline_parallel_size = \
  225. self.parallel_config.pipeline_parallel_size
  226. self.cached_scheduler_outputs = [
  227. SchedulerOutputState() for _ in range(pipeline_parallel_size)
  228. ]
  229. async def step_async(
  230. self, virtual_engine: int
  231. ) -> List[Union[RequestOutput, EmbeddingRequestOutput]]:
  232. """Performs one decoding iteration and returns newly generated results.
  233. The workers are ran asynchronously if possible.
  234. This function performs one decoding iteration of the engine. It first
  235. schedules the sequences to be executed in the next iteration and the
  236. token blocks to be swapped in/out/copy. Then, it executes the model
  237. and updates the scheduler with the model outputs. Finally, it decodes
  238. the sequences and returns the newly generated results.
  239. """
  240. # these are cached outputs from previous iterations. None if on first
  241. # iteration
  242. cached_outputs = self.cached_scheduler_outputs[virtual_engine]
  243. seq_group_metadata_list = cached_outputs.seq_group_metadata_list
  244. scheduler_outputs = cached_outputs.scheduler_outputs
  245. # skip the scheduler if there are any remaining steps in the seq groups.
  246. # This ensures that the scheduler is only called again when the current
  247. # batch has completed.
  248. if not self._has_remaining_steps(seq_group_metadata_list):
  249. seq_group_metadata_list, scheduler_outputs = self.scheduler[
  250. virtual_engine].schedule()
  251. if (self.scheduler_config.is_multi_step
  252. and scheduler_outputs.num_lookahead_slots > 0):
  253. # cache the scheduler outputs for the next iteration if we have
  254. # lookahead slots
  255. self._cache_scheduler_outputs_for_multi_step(
  256. virtual_engine, seq_group_metadata_list, scheduler_outputs)
  257. assert seq_group_metadata_list is not None
  258. assert scheduler_outputs is not None
  259. if not scheduler_outputs.is_empty():
  260. finished_requests_ids = self.scheduler[
  261. virtual_engine].get_and_reset_finished_requests_ids()
  262. # Check if we have a cached last_output from the previous iteration.
  263. # For supporting PP this is probably the best way to pass the
  264. # sampled_token_ids, as a separate broadcast over all the PP stages
  265. # will cause one virtual engine's microbatch to block the pipeline.
  266. last_sampled_token_ids = \
  267. self._get_last_sampled_token_ids(virtual_engine)
  268. execute_model_req = ExecuteModelRequest(
  269. seq_group_metadata_list=seq_group_metadata_list,
  270. blocks_to_swap_in=scheduler_outputs.blocks_to_swap_in,
  271. blocks_to_swap_out=scheduler_outputs.blocks_to_swap_out,
  272. blocks_to_copy=scheduler_outputs.blocks_to_copy,
  273. virtual_engine=virtual_engine,
  274. num_lookahead_slots=scheduler_outputs.num_lookahead_slots,
  275. running_queue_size=scheduler_outputs.running_queue_size,
  276. finished_requests_ids=finished_requests_ids,
  277. # We use ExecuteModelRequest to pass the last sampled_token_ids
  278. # to each of the non-last PP stages for in-place prepare_input.
  279. last_sampled_token_ids=last_sampled_token_ids)
  280. # Execute the model.
  281. output = await self.model_executor.execute_model_async(
  282. execute_model_req)
  283. # we need to do this here so that last step's sampled_token_ids can
  284. # be passed to the next iteration for PP.
  285. if self.scheduler_config.is_multi_step:
  286. self._update_cached_scheduler_output(virtual_engine, output)
  287. else:
  288. output = []
  289. # Finish the current step for all the sequence groups.
  290. if self.scheduler_config.is_multi_step:
  291. for seq_group in seq_group_metadata_list:
  292. seq_group.finish_step()
  293. if not self._has_remaining_steps(seq_group_metadata_list):
  294. # clear the cache if we have finished all the steps
  295. if self.scheduler_config.is_multi_step:
  296. self.cached_scheduler_outputs[
  297. virtual_engine] = SchedulerOutputState()
  298. request_outputs = self._process_model_outputs(
  299. output, scheduler_outputs.scheduled_seq_groups,
  300. scheduler_outputs.ignored_seq_groups, seq_group_metadata_list)
  301. else:
  302. request_outputs = []
  303. # Log stats.
  304. self.do_log_stats(scheduler_outputs, output)
  305. return request_outputs
  306. def _has_remaining_steps(
  307. self, seq_group_metadata_list: Optional[List[SequenceGroupMetadata]]
  308. ) -> bool:
  309. if (not self.scheduler_config.is_multi_step
  310. or not seq_group_metadata_list):
  311. return False
  312. # TODO: this is a sanity check for now to make sure that all the
  313. # seqs are on the same steps. Eventually we will want to do some sort of
  314. # dynamic scheduling when doing multi-step decoding.
  315. ref_remaining_steps = seq_group_metadata_list[0].state.remaining_steps
  316. if any([
  317. seq_group.state.remaining_steps != ref_remaining_steps
  318. for seq_group in seq_group_metadata_list[1:]
  319. ]):
  320. raise AssertionError(("All running sequence groups should "
  321. "have the same remaining steps."))
  322. return ref_remaining_steps > 0
  323. def _cache_scheduler_outputs_for_multi_step(
  324. self, virtual_engine: int,
  325. seq_group_metadata_list: Optional[List[SequenceGroupMetadata]],
  326. scheduler_outputs: SchedulerOutputs) -> None:
  327. self.cached_scheduler_outputs[
  328. virtual_engine].seq_group_metadata_list = seq_group_metadata_list
  329. self.cached_scheduler_outputs[virtual_engine].scheduler_outputs = \
  330. scheduler_outputs
  331. self.cached_scheduler_outputs[virtual_engine].last_output = None
  332. def _get_last_sampled_token_ids(
  333. self, virtual_engine: int) -> Optional[torch.Tensor]:
  334. cached_last_output = self.cached_scheduler_outputs[
  335. virtual_engine].last_output
  336. if (self.scheduler_config.is_multi_step
  337. and self.parallel_config.pipeline_parallel_size > 1
  338. and cached_last_output is not None
  339. and cached_last_output.sampled_token_ids_cpu is not None):
  340. return cached_last_output.sampled_token_ids_cpu
  341. return None
  342. def _update_cached_scheduler_output(
  343. self, virtual_engine: int,
  344. output: List[Optional[SamplerOutput]]) -> None:
  345. if (self.parallel_config.pipeline_parallel_size > 1 and len(output) > 0
  346. and output[0] is not None):
  347. last_output = output[-1]
  348. assert last_output is not None
  349. assert last_output.sampled_token_ids_cpu is not None
  350. assert last_output.sampled_token_ids is None
  351. assert last_output.sampled_token_probs is None
  352. self.cached_scheduler_outputs[
  353. virtual_engine].last_output = last_output
  354. async def stop_remote_worker_execution_loop_async(self) -> None:
  355. """Stop the remote worker execution loop."""
  356. await self.model_executor.stop_remote_worker_execution_loop_async()
  357. async def _tokenize_prompt_async(
  358. self,
  359. prompt: str,
  360. request_id: str,
  361. lora_request: Optional[LoRARequest],
  362. ) -> List[int]:
  363. """Async version of :meth:`_tokenize_prompt`."""
  364. tokenizer = self.get_tokenizer_group("prompts must be None if "
  365. "skip_tokenizer_init is True")
  366. return await tokenizer.encode_async(request_id=request_id,
  367. prompt=prompt,
  368. lora_request=lora_request)
  369. async def _extract_prompt_components_async(
  370. self,
  371. inputs: SingletonPromptInputs,
  372. request_id: str,
  373. lora_request: Optional[LoRARequest] = None,
  374. ) -> PromptComponents:
  375. """Async version of :meth:`_extract_prompt_components`."""
  376. if isinstance(inputs, str):
  377. prompt = inputs
  378. prompt_token_ids = await self._tokenize_prompt_async(
  379. prompt,
  380. request_id=request_id,
  381. lora_request=lora_request,
  382. )
  383. multi_modal_data = None
  384. elif isinstance(inputs, dict):
  385. if "prompt_token_ids" in inputs:
  386. prompt = None
  387. prompt_token_ids = inputs["prompt_token_ids"]
  388. else:
  389. # NOTE: This extra assignment is required to pass mypy
  390. prompt = parsed_prompt = inputs["prompt"]
  391. prompt_token_ids = await self._tokenize_prompt_async(
  392. parsed_prompt,
  393. request_id=request_id,
  394. lora_request=lora_request,
  395. )
  396. multi_modal_data = inputs.get("multi_modal_data")
  397. else:
  398. assert_never(inputs)
  399. return prompt, prompt_token_ids, multi_modal_data
  400. async def _process_encoder_decoder_prompt_async(
  401. self,
  402. inputs: PromptInputs,
  403. request_id: str,
  404. ) -> EncoderDecoderLLMInputs:
  405. """Async version of :meth:`_process_encoder_decoder_prompt`."""
  406. encoder_comps: PromptComponents
  407. decoder_comps: DecoderPromptComponents
  408. if is_explicit_encoder_decoder_prompt(inputs):
  409. encoder_task = self._extract_prompt_components_async(
  410. inputs["encoder_prompt"],
  411. request_id=request_id,
  412. )
  413. if (decoder_input := inputs["decoder_prompt"]) is None:
  414. encoder_comps = await encoder_task
  415. decoder_comps = None, None, None
  416. else:
  417. decoder_task = self._extract_prompt_components_async(
  418. decoder_input,
  419. request_id=request_id,
  420. )
  421. encoder_comps, decoder_comps = await asyncio.gather(
  422. encoder_task, decoder_task)
  423. else:
  424. encoder_comps = await self._extract_prompt_components_async(
  425. inputs,
  426. request_id=request_id,
  427. )
  428. decoder_comps = None, None, None
  429. return self._build_enc_dec_llm_inputs(encoder_comps, decoder_comps)
  430. async def _process_decoder_only_prompt_async(
  431. self,
  432. inputs: SingletonPromptInputs,
  433. request_id: str,
  434. lora_request: Optional[LoRARequest] = None,
  435. prompt_adapter_request: Optional[PromptAdapterRequest] = None,
  436. ) -> LLMInputs:
  437. """Async version of :meth:`_process_decoder_only_prompt`."""
  438. prompt_comps = await self._extract_prompt_components_async(
  439. inputs,
  440. request_id=request_id,
  441. lora_request=lora_request,
  442. )
  443. return self._build_decoder_only_llm_inputs(
  444. prompt_comps,
  445. prompt_adapter_request=prompt_adapter_request,
  446. )
  447. async def process_model_inputs_async(
  448. self,
  449. inputs: PromptInputs,
  450. request_id: str,
  451. lora_request: Optional[LoRARequest] = None,
  452. prompt_adapter_request: Optional[PromptAdapterRequest] = None,
  453. ) -> Union[LLMInputs, EncoderDecoderLLMInputs]:
  454. """Async version of :meth:`process_model_inputs`."""
  455. if self.is_encoder_decoder_model():
  456. # Encoder-decoder model requires special mapping of
  457. # input prompts to encoder & decoder
  458. model_inputs = await self._process_encoder_decoder_prompt_async(
  459. inputs,
  460. request_id=request_id,
  461. )
  462. else:
  463. if is_explicit_encoder_decoder_prompt(inputs):
  464. raise ValueError("Cannot pass encoder-decoder prompt "
  465. "to decoder-only models")
  466. # Decoder-only operation
  467. model_inputs = await self._process_decoder_only_prompt_async(
  468. inputs,
  469. request_id=request_id,
  470. lora_request=lora_request,
  471. prompt_adapter_request=prompt_adapter_request,
  472. )
  473. return self.input_processor(model_inputs)
  474. async def add_request_async(
  475. self,
  476. request_id: str,
  477. inputs: PromptInputs,
  478. params: Union[SamplingParams, PoolingParams],
  479. arrival_time: Optional[float] = None,
  480. lora_request: Optional[LoRARequest] = None,
  481. prompt_adapter_request: Optional[PromptAdapterRequest] = None,
  482. ) -> None:
  483. """Async version of :meth:`add_request`."""
  484. if lora_request is not None and not self.lora_config:
  485. raise ValueError(f"Got lora_request {lora_request} but LoRA is "
  486. "not enabled!")
  487. if arrival_time is None:
  488. arrival_time = time.time()
  489. processed_inputs = await self.process_model_inputs_async(
  490. inputs,
  491. request_id=request_id,
  492. lora_request=lora_request,
  493. prompt_adapter_request=prompt_adapter_request,
  494. )
  495. self._add_processed_request(
  496. request_id=request_id,
  497. processed_inputs=processed_inputs,
  498. params=params,
  499. arrival_time=arrival_time,
  500. lora_request=lora_request,
  501. prompt_adapter_request=prompt_adapter_request,
  502. )
  503. async def check_health_async(self) -> None:
  504. if self.tokenizer:
  505. self.tokenizer.check_health()
  506. self.model_executor.check_health()
  507. class AsyncAphrodite:
  508. """An asynchronous wrapper for AphroditeEngine.
  509. This class is used to wrap the AphroditeEngine class to make it
  510. asynchronous. It uses asyncio to create a background loop that keeps
  511. processing incoming requests. The AphroditeEngine is kicked by the
  512. generate method when there are requests in the waiting queue.
  513. The generate method yields the outputs from the AphroditeEngine
  514. to the caller.
  515. NOTE: For the comprehensive list of arguments, see `AphroditeEngine`.
  516. Args:
  517. worker_use_ray: Whether to use Ray for model workers. Required for
  518. distributed execution. Should be the same as
  519. `parallel_config.worker_use_ray`.
  520. engine_use_ray: Whether to make AphroditeEngine a Ray actor. If so, the
  521. async frontend will be executed in a separate process as the
  522. model workers.
  523. log_requests: Whether to log the requests.
  524. start_engine_loop: If True, the background task to run the engine
  525. will be automatically started in the generate call.
  526. *args: Arguments for AphroditeEngine.
  527. *kwargs: Arguments for AphroditeEngine.
  528. """
  529. _engine_class: Type[_AsyncAphrodite] = _AsyncAphrodite
  530. def __init__(self,
  531. worker_use_ray: bool,
  532. engine_use_ray: bool,
  533. *args,
  534. log_requests: bool = True,
  535. start_engine_loop: bool = True,
  536. **kwargs) -> None:
  537. self.worker_use_ray = worker_use_ray
  538. self.engine_use_ray = engine_use_ray
  539. self.log_requests = log_requests
  540. self.engine = self._init_engine(*args, **kwargs)
  541. self.background_loop: Optional[asyncio.Future] = None
  542. # We need to keep a reference to unshielded
  543. # task as well to prevent it from being garbage
  544. # collected
  545. self._background_loop_unshielded: Optional[asyncio.Task] = None
  546. self.start_engine_loop = start_engine_loop
  547. self._errored_with: Optional[BaseException] = None
  548. # Lazy initialized fields
  549. self._request_tracker: RequestTracker
  550. @classmethod
  551. def _get_executor_cls(
  552. cls, engine_config: EngineConfig) -> Type[ExecutorAsyncBase]:
  553. distributed_executor_backend = (
  554. engine_config.parallel_config.distributed_executor_backend)
  555. if isinstance(distributed_executor_backend, type):
  556. if not issubclass(distributed_executor_backend, ExecutorAsyncBase):
  557. raise TypeError(
  558. "distributed_executor_backend must be a subclass of "
  559. f"ExecutorAsyncBase. Got {distributed_executor_backend}.")
  560. if distributed_executor_backend.uses_ray: # type: ignore
  561. initialize_ray_cluster(engine_config.parallel_config)
  562. executor_class = distributed_executor_backend
  563. elif engine_config.device_config.device_type == "neuron":
  564. from aphrodite.executor.neuron_executor import NeuronExecutorAsync
  565. executor_class = NeuronExecutorAsync
  566. elif engine_config.device_config.device_type == "tpu":
  567. if distributed_executor_backend == "ray":
  568. initialize_ray_cluster(engine_config.parallel_config)
  569. from aphrodite.executor.ray_tpu_executor import (
  570. RayTPUExecutorAsync)
  571. executor_class = RayTPUExecutorAsync
  572. else:
  573. assert distributed_executor_backend is None
  574. from aphrodite.executor.tpu_executor import TPUExecutorAsync
  575. executor_class = TPUExecutorAsync
  576. elif engine_config.device_config.device_type == "cpu":
  577. from aphrodite.executor.cpu_executor import CPUExecutorAsync
  578. executor_class = CPUExecutorAsync
  579. elif engine_config.device_config.device_type == "openvino":
  580. assert distributed_executor_backend is None, (
  581. "Distributed execution is not supported with the OpenVINO "
  582. "backend.")
  583. from aphrodite.executor.openvino_executor import (
  584. OpenVINOExecutorAsync)
  585. executor_class = OpenVINOExecutorAsync
  586. elif engine_config.device_config.device_type == "xpu":
  587. if distributed_executor_backend is None:
  588. from aphrodite.executor.xpu_executor import XPUExecutorAsync
  589. executor_class = XPUExecutorAsync
  590. elif distributed_executor_backend == "ray":
  591. initialize_ray_cluster(engine_config.parallel_config)
  592. from aphrodite.executor.ray_xpu_executor import (
  593. RayXPUExecutorAsync)
  594. executor_class = RayXPUExecutorAsync
  595. else:
  596. raise RuntimeError(
  597. "Unsupported distributed executor backend for XPU.")
  598. elif distributed_executor_backend == "ray":
  599. initialize_ray_cluster(engine_config.parallel_config)
  600. from aphrodite.executor.ray_gpu_executor import RayGPUExecutorAsync
  601. executor_class = RayGPUExecutorAsync
  602. elif distributed_executor_backend == "mp":
  603. from aphrodite.executor.multiproc_gpu_executor import (
  604. MultiprocessingGPUExecutorAsync)
  605. executor_class = MultiprocessingGPUExecutorAsync
  606. else:
  607. from aphrodite.executor.gpu_executor import GPUExecutorAsync
  608. executor_class = GPUExecutorAsync
  609. return executor_class
  610. @classmethod
  611. def from_engine_args(
  612. cls,
  613. engine_args: AsyncEngineArgs,
  614. start_engine_loop: bool = True,
  615. stat_loggers: Optional[Dict[str, StatLoggerBase]] = None,
  616. ) -> "AsyncAphrodite":
  617. """Creates an async LLM engine from the engine arguments."""
  618. # Create the engine configs.
  619. engine_config = engine_args.create_engine_config()
  620. if engine_args.engine_use_ray:
  621. from aphrodite.executor import ray_utils
  622. ray_utils.assert_ray_available()
  623. executor_class = cls._get_executor_cls(engine_config)
  624. # Create the async LLM engine.
  625. engine = cls(
  626. executor_class.uses_ray,
  627. engine_args.engine_use_ray,
  628. **engine_config.to_dict(),
  629. executor_class=executor_class,
  630. log_requests=not engine_args.disable_log_requests,
  631. log_stats=not engine_args.disable_log_stats,
  632. start_engine_loop=start_engine_loop,
  633. stat_loggers=stat_loggers,
  634. )
  635. return engine
  636. @property
  637. def is_running(self) -> bool:
  638. return (self.background_loop is not None
  639. and self._background_loop_unshielded is not None
  640. and not self._background_loop_unshielded.done())
  641. @property
  642. def is_stopped(self) -> bool:
  643. return self.errored or (self.background_loop is not None and
  644. self._background_loop_unshielded is not None
  645. and self._background_loop_unshielded.done())
  646. @property
  647. def errored(self) -> bool:
  648. return self._errored_with is not None
  649. @property
  650. def limit_concurrency(self) -> Optional[int]:
  651. """Maximum number of concurrently running requests."""
  652. return None
  653. def set_errored(self, exc: Exception) -> None:
  654. self._errored_with = exc
  655. def _error_callback(self, exc: Exception) -> None:
  656. self.set_errored(exc)
  657. self._request_tracker.propagate_exception(exc)
  658. async def get_tokenizer(
  659. self,
  660. lora_request: Optional[LoRARequest] = None,
  661. ) -> "PreTrainedTokenizer":
  662. if self.engine_use_ray:
  663. return await self.engine.get_tokenizer.remote( # type: ignore
  664. lora_request)
  665. return await (self.engine.get_tokenizer_group().
  666. get_lora_tokenizer_async(lora_request))
  667. def start_background_loop(self) -> None:
  668. """Start the background loop."""
  669. if self.errored:
  670. raise AsyncEngineDeadError(
  671. "Background loop has errored already.") from self._errored_with
  672. if self.is_running:
  673. raise RuntimeError("Background loop is already running.")
  674. # Initialize the RequestTracker here so it uses the right event loop.
  675. self._request_tracker = RequestTracker()
  676. self._background_loop_unshielded = asyncio.get_event_loop(
  677. ).create_task(self.run_engine_loop())
  678. self._background_loop_unshielded.add_done_callback(
  679. partial(_log_task_completion, error_callback=self._error_callback))
  680. self.background_loop = asyncio.shield(self._background_loop_unshielded)
  681. def shutdown_background_loop(self) -> None:
  682. """
  683. Shut down the background loop.
  684. This method needs to be called during cleanup to remove
  685. references to `self` and properly GC the resources held
  686. by the async LLM engine (e.g., the executors as well as
  687. their resources).
  688. """
  689. if self._background_loop_unshielded is not None:
  690. self._background_loop_unshielded.cancel()
  691. self._background_loop_unshielded = None
  692. self.background_loop = None
  693. def _init_engine(self, *args,
  694. **kwargs) -> Union[_AsyncAphrodite, "ray.ObjectRef"]:
  695. if not self.engine_use_ray:
  696. engine_class = self._engine_class
  697. elif self.worker_use_ray:
  698. engine_class = ray.remote(num_cpus=0)(self._engine_class).remote
  699. else:
  700. # FIXME: This is a bit hacky. Be careful when changing the
  701. # order of the arguments.
  702. cache_config = kwargs["cache_config"]
  703. parallel_config = kwargs["parallel_config"]
  704. if (parallel_config.tensor_parallel_size == 1
  705. and parallel_config.pipeline_parallel_size == 1):
  706. num_gpus = cache_config.gpu_memory_utilization
  707. else:
  708. num_gpus = 1
  709. engine_class = ray.remote(num_gpus=num_gpus)(
  710. self._engine_class).remote
  711. return engine_class(*args, **kwargs)
  712. async def engine_step(self, virtual_engine: int) -> bool:
  713. """Kick the engine to process the waiting requests.
  714. Returns True if there are in-progress requests."""
  715. new_requests, aborted_requests = (
  716. self._request_tracker.get_new_and_aborted_requests())
  717. for new_request in new_requests:
  718. # Add the request into the Aphrodite engine's waiting queue.
  719. # TODO: Maybe add add_request_batch to reduce Ray overhead
  720. try:
  721. if self.engine_use_ray:
  722. await self.engine.add_request.remote( # type: ignore
  723. **new_request)
  724. else:
  725. await self.engine.add_request_async(**new_request)
  726. except ValueError as e:
  727. # TODO: use an Aphrodite specific error for failed validation
  728. self._request_tracker.process_exception(
  729. new_request["request_id"],
  730. e,
  731. verbose=self.log_requests,
  732. )
  733. if aborted_requests:
  734. await self._engine_abort(aborted_requests)
  735. if self.engine_use_ray:
  736. request_outputs = await self.engine.step.remote() # type: ignore
  737. else:
  738. request_outputs = await self.engine.step_async(virtual_engine)
  739. # Put the outputs into the corresponding streams.
  740. finished = True
  741. for request_output in request_outputs:
  742. self._request_tracker.process_request_output(
  743. request_output, verbose=self.log_requests)
  744. finished = finished and request_output.finished
  745. return not finished
  746. async def _engine_abort(self, request_ids: Iterable[str]):
  747. if self.engine_use_ray:
  748. await self.engine.abort_request.remote(request_ids) # type: ignore
  749. else:
  750. self.engine.abort_request(request_ids)
  751. async def run_engine_loop(self):
  752. if self.engine_use_ray:
  753. pipeline_parallel_size = 1 # type: ignore
  754. else:
  755. pipeline_parallel_size = \
  756. self.engine.parallel_config.pipeline_parallel_size
  757. has_requests_in_progress = [False] * pipeline_parallel_size
  758. while True:
  759. if not any(has_requests_in_progress):
  760. logger.debug("Waiting for new requests...")
  761. # Stop the execute model loop in parallel workers until there
  762. # are more requests to process. This avoids waiting
  763. # indefinitely in torch.distributed ops which may otherwise
  764. # timeout, and unblocks the RPC thread in the workers so that
  765. # they can process any other queued control plane messages,
  766. # such as add/remove lora adapters.
  767. if self.engine_use_ray:
  768. await (self.engine.stop_remote_worker_execution_loop.
  769. remote() # type: ignore
  770. )
  771. else:
  772. await self.engine.stop_remote_worker_execution_loop_async()
  773. await self._request_tracker.wait_for_new_requests()
  774. logger.debug("Got new requests!")
  775. requests_in_progress = [
  776. asyncio.create_task(self.engine_step(ve))
  777. for ve in range(pipeline_parallel_size)
  778. ]
  779. has_requests_in_progress = [True] * pipeline_parallel_size
  780. # Abort if iteration takes too long due to unrecoverable errors
  781. # (eg. NCCL timeouts).
  782. try:
  783. async with asyncio_timeout(ENGINE_ITERATION_TIMEOUT_S):
  784. done, _ = await asyncio.wait(
  785. requests_in_progress,
  786. return_when=asyncio.FIRST_COMPLETED)
  787. for _ in range(pipeline_parallel_size):
  788. await asyncio.sleep(0)
  789. for task in done:
  790. result = task.result()
  791. virtual_engine = requests_in_progress.index(task)
  792. if self.engine_use_ray:
  793. has_unfinished_requests = (
  794. await (self.engine.
  795. has_unfinished_requests_for_virtual_engine.
  796. remote( # type: ignore
  797. virtual_engine)))
  798. else:
  799. has_unfinished_requests = (
  800. self.engine.
  801. has_unfinished_requests_for_virtual_engine(
  802. virtual_engine))
  803. if result or has_unfinished_requests:
  804. requests_in_progress[virtual_engine] = (
  805. asyncio.create_task(
  806. self.engine_step(virtual_engine)))
  807. has_requests_in_progress[virtual_engine] = True
  808. else:
  809. has_requests_in_progress[virtual_engine] = False
  810. except asyncio.TimeoutError as exc:
  811. logger.error(
  812. "Engine iteration timed out. This should never happen!")
  813. self.set_errored(exc)
  814. raise
  815. await asyncio.sleep(0)
  816. # This method does not need to be async, but kept that way
  817. # for backwards compatibility.
  818. async def add_request(
  819. self,
  820. request_id: str,
  821. inputs: PromptInputs,
  822. params: Union[SamplingParams, PoolingParams],
  823. arrival_time: Optional[float] = None,
  824. lora_request: Optional[LoRARequest] = None,
  825. prompt_adapter_request: Optional[PromptAdapterRequest] = None,
  826. ) -> AsyncGenerator[Union[RequestOutput, EmbeddingRequestOutput], None]:
  827. if not self.is_running:
  828. if self.start_engine_loop:
  829. self.start_background_loop()
  830. else:
  831. raise AsyncEngineDeadError(
  832. "Background loop is not running. If it was running, "
  833. "inspect the output to find the stacktrace of the "
  834. "error that caused the background loop to stop "
  835. "(AsyncEngineDeadError).")
  836. stream = self._request_tracker.add_request(
  837. request_id,
  838. verbose=self.log_requests,
  839. inputs=inputs,
  840. params=params,
  841. arrival_time=arrival_time or time.time(),
  842. lora_request=lora_request,
  843. prompt_adapter_request=prompt_adapter_request)
  844. return stream.generator()
  845. async def generate(
  846. self,
  847. inputs: PromptInputs,
  848. sampling_params: SamplingParams,
  849. request_id: str,
  850. lora_request: Optional[LoRARequest] = None,
  851. prompt_adapter_request: Optional[PromptAdapterRequest] = None,
  852. ) -> AsyncGenerator[RequestOutput, None]:
  853. """Generate outputs for a request.
  854. Generate outputs for a request. This method is a coroutine. It adds the
  855. request into the waiting queue of the AphroditeEngine and streams the
  856. outputs from the AphroditeEngine to the caller.
  857. Args:
  858. prompt: The prompt string. Can be None if prompt_token_ids is
  859. provided.
  860. sampling_params: The sampling parameters of the request.
  861. request_id: The unique id of the request.
  862. prompt_token_ids: The token IDs of the prompt. If None, we
  863. use the tokenizer to convert the prompts to token IDs.
  864. lora_request: LoRA request to use for generation, if any.
  865. prompt_adapter_request: Prompt Adapter request to use
  866. for generation, if any.
  867. Yields:
  868. The output `RequestOutput` objects from the AphroditeEngine
  869. for the request.
  870. Details:
  871. - If the engine is not running, start the background loop,
  872. which iteratively invokes
  873. # pylint: disable=line-too-long
  874. :meth:`~aphrodite.engine.async_aphrodite.AsyncAphrodite.engine_step`
  875. to process the waiting requests.
  876. - Add the request to the engine's `RequestTracker`.
  877. On the next background loop, this request will be sent to
  878. the underlying engine.
  879. Also, a corresponding `AsyncStream` will be created.
  880. - Wait for the request outputs from `AsyncStream` and yield them.
  881. Example:
  882. >>> # Please refer to entrypoints/api_server.py for
  883. >>> # the complete example.
  884. >>>
  885. >>> # initialize the engine and the example input
  886. >>> engine = AsyncAphrodite.from_engine_args(engine_args)
  887. >>> example_input = {
  888. >>> "prompt": "What is LLM?",
  889. >>> "stream": False, # assume the non-streaming case
  890. >>> "temperature": 0.0,
  891. >>> "request_id": 0,
  892. >>> }
  893. >>>
  894. >>> # start the generation
  895. >>> results_generator = engine.generate(
  896. >>> example_input["prompt"],
  897. >>> SamplingParams(temperature=example_input["temperature"]),
  898. >>> example_input["request_id"])
  899. >>>
  900. >>> # get the results
  901. >>> final_output = None
  902. >>> async for request_output in results_generator:
  903. >>> if await request.is_disconnected():
  904. >>> # Abort the request if the client disconnects.
  905. >>> await engine.abort(request_id)
  906. >>> # Return or raise an error
  907. >>> ...
  908. >>> final_output = request_output
  909. >>>
  910. >>> # Process and return the final output
  911. >>> ...
  912. """
  913. async for output in await self.add_request(
  914. request_id,
  915. inputs,
  916. sampling_params,
  917. lora_request=lora_request,
  918. prompt_adapter_request=prompt_adapter_request,
  919. ):
  920. yield AphroditeEngine.validate_output(output, RequestOutput)
  921. async def encode(
  922. self,
  923. inputs: PromptInputs,
  924. pooling_params: PoolingParams,
  925. request_id: str,
  926. lora_request: Optional[LoRARequest] = None,
  927. ) -> AsyncGenerator[EmbeddingRequestOutput, None]:
  928. """Generate outputs for a request from an embedding model.
  929. Generate outputs for a request. This method is a coroutine. It adds the
  930. request into the waiting queue of the AphroditeEngine and streams the
  931. outputs from the AphroditeEngine to the caller.
  932. Args:
  933. prompt: The prompt string. Can be None if prompt_token_ids is
  934. provided.
  935. pooling_params: The pooling parameters of the request.
  936. request_id: The unique id of the request.
  937. prompt_token_ids: The token IDs of the prompt. If None, we
  938. use the tokenizer to convert the prompts to token IDs.
  939. lora_request: LoRA request to use for generation, if any.
  940. multi_modal_data: Multi modal data per request.
  941. Yields:
  942. The output `EmbeddingRequestOutput` objects from the
  943. AphroditeEngine for the request.
  944. Details:
  945. - If the engine is not running, start the background loop,
  946. which iteratively invokes
  947. :meth:`~aphrodite.engine.async_aphrodite.AsyncAphrodite.engine_step`
  948. to process the waiting requests.
  949. - Add the request to the engine's `RequestTracker`.
  950. On the next background loop, this request will be sent to
  951. the underlying engine.
  952. Also, a corresponding `AsyncStream` will be created.
  953. - Wait for the request outputs from `AsyncStream` and yield them.
  954. Example:
  955. >>> # initialize the engine and the example input
  956. >>> engine = AsyncAphrodite.from_engine_args(engine_args)
  957. >>> example_input = {
  958. >>> "input": "What is LLM?",
  959. >>> "request_id": 0,
  960. >>> }
  961. >>>
  962. >>> # start the generation
  963. >>> results_generator = engine.encode(
  964. >>> example_input["input"],
  965. >>> PoolingParams(),
  966. >>> example_input["request_id"])
  967. >>>
  968. >>> # get the results
  969. >>> final_output = None
  970. >>> async for request_output in results_generator:
  971. >>> if await request.is_disconnected():
  972. >>> # Abort the request if the client disconnects.
  973. >>> await engine.abort(request_id)
  974. >>> # Return or raise an error
  975. >>> ...
  976. >>> final_output = request_output
  977. >>>
  978. >>> # Process and return the final output
  979. >>> ...
  980. """
  981. async for output in await self.add_request(
  982. request_id,
  983. inputs,
  984. pooling_params,
  985. lora_request=lora_request,
  986. ):
  987. yield AphroditeEngine.validate_output(output,
  988. EmbeddingRequestOutput)
  989. async def abort(self, request_id: str) -> None:
  990. """Abort a request.
  991. Abort a submitted request. If the request is finished or not found,
  992. this method will be a no-op.
  993. Args:
  994. request_id: The unique id of the request.
  995. """
  996. if not self.is_running:
  997. raise AsyncEngineDeadError(
  998. "Background loop is not running. If it was running, "
  999. "inspect the output to find the stacktrace of the "
  1000. "error that caused the background loop to stop "
  1001. "(AsyncEngineDeadError).")
  1002. return self._abort(request_id)
  1003. def _abort(self, request_id: str) -> None:
  1004. """Abort a request.
  1005. Abort a submitted request. If the request is finished or not found,
  1006. this method will be a no-op.
  1007. Args:
  1008. request_id: The unique id of the request.
  1009. """
  1010. self._request_tracker.abort_request(request_id,
  1011. exception=asyncio.CancelledError,
  1012. verbose=self.log_requests)
  1013. async def get_model_config(self) -> ModelConfig:
  1014. """Get the model configuration of the Aphrodite engine."""
  1015. if self.engine_use_ray:
  1016. return await self.engine.get_model_config.remote() # type: ignore
  1017. else:
  1018. return self.engine.get_model_config()
  1019. async def get_parallel_config(self) -> ParallelConfig:
  1020. """Get the parallel configuration of the Aphrodite engine."""
  1021. if self.engine_use_ray:
  1022. return await self.engine.get_parallel_config.remote( # type: ignore
  1023. )
  1024. else:
  1025. return self.engine.get_parallel_config()
  1026. async def get_decoding_config(self) -> DecodingConfig:
  1027. """Get the decoding configuration of the Aphrodite engine."""
  1028. if self.engine_use_ray:
  1029. return await self.engine.get_decoding_config.remote( # type: ignore
  1030. )
  1031. else:
  1032. return self.engine.get_decoding_config()
  1033. async def get_scheduler_config(self) -> SchedulerConfig:
  1034. """Get the scheduling configuration of the Aphrodite engine."""
  1035. if self.engine_use_ray:
  1036. return await self.engine.get_scheduler_config.remote( # type: ignore
  1037. )
  1038. else:
  1039. return self.engine.get_scheduler_config()
  1040. async def get_lora_config(self) -> LoRAConfig:
  1041. """Get the lora configuration of the Aphrodite engine."""
  1042. if self.engine_use_ray:
  1043. return await self.engine.get_lora_config.remote( # type: ignore
  1044. )
  1045. else:
  1046. return self.engine.get_lora_config()
  1047. async def do_log_stats(
  1048. self,
  1049. scheduler_outputs: Optional[SchedulerOutputs] = None,
  1050. model_output: Optional[List[SamplerOutput]] = None) -> None:
  1051. if self.engine_use_ray:
  1052. await self.engine.do_log_stats.remote( # type: ignore
  1053. scheduler_outputs, model_output)
  1054. else:
  1055. self.engine.do_log_stats()
  1056. async def check_health(self) -> None:
  1057. """Raises an error if engine is unhealthy."""
  1058. t = time.perf_counter()
  1059. logger.debug("Starting health check...")
  1060. if self.is_stopped:
  1061. raise AsyncEngineDeadError("Background loop is stopped.")
  1062. if self.engine_use_ray:
  1063. try:
  1064. await self.engine.check_health.remote() # type: ignore
  1065. except ray.exceptions.RayActorError as e:
  1066. raise RuntimeError("Engine is dead.") from e
  1067. else:
  1068. await self.engine.check_health_async()
  1069. logger.debug(f"Health check took {time.perf_counter()-t}s")