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

オープン
  • 何か問題がありますか？
#644 コメント 1 件 リアクション 0 件 担当者 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時間
マージ済み PR（30日）
34

環境構築

はじめの一歩

  1. issue を最後まで読み、次にプロジェクトのコントリビューションガイドを読みます。
  2. 着手することを issue にコメントします — 二人が同じ作業をするのを防げます。
  3. リポジトリをフォークし、ブランチを切って変更します。
  4. issue 番号を参照したプルリクエストを送ります。

temporalio/sdk-ruby のほかの issue

temporalio/sdk-ruby の issue をすべて見る

似ている issue

Ruby の issue をもっと見る

新しい issue をメールで受け取る

初心者向けの GitHub issue を短くまとめたダイジェスト。