Repository navigation
Description
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
endEnable 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
chris-olszewski commentedon Nov 4, 2026
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.