Skip to content

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

Open

Description

@chris-olszewski

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)

Activity

  1. chris-olszewski commented on Nov 4, 2026

    @chris-olszewski
    MemberAuthor

    Following up on this: general guidance for now if you are hitting this is to disable illegal call tracing in production, but keep it enabled for testing workflow code where it should capture illegal calls.

    Fixing this in the general sense ends up being invasive and I don't want to rush into a poor solution.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Labels

bugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions