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

Open
  • Is something wrong?
#644 1 comment 0 reactions 1 assignee View on GitHub

Maintainers usually reply within 1 day

@chris-olszewski is already working on this.

Since Oct 28, 2026.

Assessment

This issue has not been assessed yet.

Description

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)
Dominant language
Ruby
Stars
207
Forks
46
Avg merge
1d 15h
Merged PRs (30d)
34

Getting set up

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from temporalio/sdk-ruby

All issues in temporalio/sdk-ruby

Similar issues

More Ruby issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.