[Bug] Illegal call tracing enabling scales with memory slowing down WFT execution

未关闭
  • 哪里不对？
#644 1 条评论 0 个 reaction 已指派 1 人 在 GitHub 查看

维护者通常 1 天内回复

@chris-olszewski 已经在做这个了。

开始于 2026年10月28日。

评估

这个 Issue 还没有评估数据。

描述

bug

Extracted from #643

Describe the bug

The tracer calls TracePoint#enable around every activation, and that call costs time in proportion to the number of live heap objects: 1.7ms at 1.1M objects and 8.6ms at 5.3M (YJIT on, no extra code loaded). A booted Rails 8 app with about 1.05M objects pays 5.9ms per enable with YJIT on. A worker that replays a long history after a cache miss pays this once per replayed activation, so in production we saw replays run past the 10s workflow task timeout (TIMEOUT_TYPE_START_TO_CLOSE), with every retry replaying the full history again.

Full replay of a 1,500-timer history (about 7,500 events) on a fresh worker, YJIT on, about 1.2M live objects, two runs each:

main illegal_workflow_calls: {} This branch
Replay task duration 16.5s, 23.1s 0.58s, 0.91s 0.40s, 0.38s

[!IMPORTANT]
Separate gap on main: code after an await is not traced. Resolving a timer, activity, child workflow, Nexus operation or external signal/cancel resumes the waiting fiber from activation.jobs.each { apply(job) }, which runs before @tracer.enable { ... }. The code right after Workflow.sleep or execute_activity returns therefore runs untraced on every activation. For example, Workflow.sleep(0.1) followed by Time.now completes on 1.10.0 without raising. This PR does not change that. I can send a separate fix that applies jobs inside the tracer block.

A replayed activation's code was traced when that activation first ran. The replay-only case happens when workflow code changes after a history was recorded, or in code that branches on Workflow::Unsafe.replaying?. WorkflowReplayer still catches it before a deploy. Core's nondeterminism check and the deadlock detector are unchanged.

If we want to keep the current behavior the default, I can expose the flag as a worker option defaulting to true.

I also tried leaving the tracer enabled per workflow thread. It removes the per-activation cost, but an enabled :call/:c_call TracePoint slows every thread, even with target_thread:: a thread running other work went from 248 to 212 iterations/s (301 with no tracer).

Minimal Reproduction
Replay benchmark script

Start temporal server start-dev --port 7244. The build step takes about 30 minutes because the dev server fires 1ms timers about once per second.

# ruby --yjit replay_bench.rb build bench-1500 1500
# ruby --yjit replay_bench.rb replay bench-1500 tracer   # or: off
require 'temporalio/client'
require 'temporalio/worker'

class ReplayBenchWorkflow < Temporalio::Workflow::Definition
  workflow_signal
  def go = @go = true

  def execute(timers)
    timers.times { Temporalio::Workflow.sleep(0.001) }
    loop do
      @go = false
      Temporalio::Workflow.wait_condition { @go }
    end
  end
end

cmd, workflow_id, arg = ARGV
client = Temporalio::Client.connect('localhost:7244', 'default')
task_queue = 'replay-bench'

if cmd == 'replay'
  $ballast = Array.new(1_000_000) { |i| "s#{i}" }
  GC.start
end

options = { client:, task_queue:, workflows: [ReplayBenchWorkflow] }
options[:illegal_workflow_calls] = {} if cmd == 'replay' && arg == 'off'

Temporalio::Worker.new(**options).run do
  if cmd == 'build'
    handle = client.start_workflow(ReplayBenchWorkflow, Integer(arg), id: workflow_id, task_queue:, task_timeout: 60)
    sleep 0.5 until handle.fetch_history_events.count(&:timer_fired_event_attributes) >= Integer(arg)
  else
    handle = client.workflow_handle(workflow_id)
    before = handle.fetch_history_events.to_a.size
    handle.signal(ReplayBenchWorkflow.go)
    events = []
    until events.drop(before).any?(&:workflow_task_completed_event_attributes)
      sleep 0.2
      events = handle.fetch_history_events.to_a
    end
    started = events.drop(before).find(&:workflow_task_started_event_attributes)
    completed = events.drop(before).find(&:workflow_task_completed_event_attributes)
    puts format('mode=%s replay_task=%.0fms', arg, (completed.event_time.to_time - started.event_time.to_time) * 1000)
  end
end
Enable cost script 
# OBJS=1000000 ruby --yjit enable_cost.rb
junk = Array.new(Integer(ENV.fetch('OBJS', '1000000'))) { |i| "s#{i}" }
tp = TracePoint.new(:call, :c_call) {}
tp.enable {}
t = Process.clock_gettime(Process::CLOCK_MONOTONIC)
50.times { tp.enable {} }
puts format('%.3fms per enable', (Process.clock_gettime(Process::CLOCK_MONOTONIC) - t) / 50 * 1000)
主要语言
Ruby
星标
207
派生
46
平均合并
1 天 15 小时
30 天内合并 PR
34

环境准备

  • 没有 Dockerfile 或 Docker Compose 文件
  • 没有 Pull Request 模板
  • 阅读贡献指南

从这里开始

  1. 先读完整个 Issue，再读项目的贡献指南。
  2. 在 Issue 下留言说明你要接手 —— 这能避免两个人做同样的事。
  3. Fork 仓库，在一个分支上完成修改。
  4. 提交 Pull Request，并在描述里引用这个 Issue 编号。

temporalio/sdk-ruby 的其他 Issue

查看 temporalio/sdk-ruby 的全部 Issue

相似的 Issue

更多 Ruby Issue

把新 issue 发到你的邮箱

精选适合新手参与的 GitHub issue 摘要。