理解与slow_callback_duration关联的asyncio set_result行为及慢回调排查

• 这类日志的计时逻辑存在普遍误解：slow_callback_duration统计的耗时，是事件循环从取出目标Handle到完成该Handle全部嵌套执行链路的总时长，并非仅统计Handle本身指向的函数代码的运行时间。
• 日志中标注的Handle创建位置（也就是你看到的asyncio/tasks.py:711），记录的是这个回调对象被生成、排入事件循环待执行队列时的代码位置，和回调实际被执行时的运行栈完全无关。
• TaskWakeupMethWrapper、gather逻辑里的set_result本身都是极薄的赋值、状态切换逻辑，单帧执行耗时都是微秒级，根本不可能达到0.1秒级的阻塞时长。这类日志报慢，本质是唤醒逻辑触发后，在同一个事件循环执行上下文里，后续连续运行的业务代码占满了执行时间。

完整流程对应你看到的日志：

1. 你用asyncio.gather封装的所有子任务执行完成，进入gather的完成回调逻辑，给外层gather Future赋值结果，同时把“唤醒挂起在这个Future上的业务Task”对应的TaskWakeupMethWrapper排入事件循环的待执行队列。
2. 事件循环当时正在跑其他同步阻塞逻辑，这个排队的Handle必须等当前阻塞逻辑执行完，才能被从队列里取出。
3. 当Handle被真正执行时，会把之前挂起的业务Task状态置为可运行，并在当前同步上下文里直接推进Task到下一次挂起点。这时候你写的、之前挂在await语句后面的所有同步逻辑——比如大对象序列化、JSON硬解析、字典遍历、同步调用第三方库接口之类——全部会在这个Handle的执行链路里跑完。
4. 这整段同步逻辑的耗时，会全部被算到这个唤醒wrapper的头上，最终输出成你看到的“wrapper执行耗时过长”的日志，看起来就像是那几行set_result代码跑了几百毫秒。

• 给事件循环补充全栈打点：原生asyncio的慢回调日志默认不会输出执行时的运行栈，你可以自定义事件循环的异常处理器，在捕获到慢回调告警时直接打印当前事件循环线程的全栈，就能看到当时正在运行的具体代码位置。可直接复用的代码逻辑：

  import traceback
  def slow_callback_trace_handler(loop, context):
      log_text = context.get("message", "")
      if "took" in log_text:
          print(">>> 慢回调触发时刻的运行栈")
          traceback.print_stack()
      loop.default_exception_handler(context)
  loop.set_exception_handler(slow_callback_trace_handler)
  

• 无侵入栈采样定位：服务运行过程中，对主进程的事件循环线程做高频栈采样，统计各代码块的执行时间占比，不需要修改业务代码逻辑，也不会大幅提升服务负载，能直接定位到事件循环上占时最长的同步代码段。
• 注意uvloop的调试兼容性局限：uvloop对asyncio调试模式的打点实现和原生事件循环存在差异，部分场景下的慢回调统计精度不足，可以短时间切换为原生asyncio运行复现问题，配合原生的慢回调规则定位阻塞点。

内容的提问来源于stack exchange，提问作者Jonas Bauer