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

Đang mở
  • Có gì không ổn?
#644 1 bình luận 0 reaction 1 người được giao Xem trên GitHub

Maintainer thường phản hồi trong vòng 1 ngày

@chris-olszewski đang làm issue này rồi.

Từ ngày 28/10/2026.

Đánh giá

Issue này chưa được đánh giá.

Mô tả

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)
Ngôn ngữ chính
Ruby
Star
207
Fork
46
Merge trung bình
1 ngày 15 giờ
Pull request đã merge (30 ngày)
34

Chuẩn bị môi trường

Bắt đầu từ đâu

  1. Đọc hết issue, rồi đọc hướng dẫn đóng góp của dự án.
  2. Bình luận trên issue rằng bạn sẽ nhận — tránh hai người làm cùng một việc.
  3. Fork repository và làm thay đổi trên một nhánh.
  4. Mở pull request có tham chiếu số hiệu của issue.

Issue khác của temporalio/sdk-ruby

Tất cả issue của temporalio/sdk-ruby

Issue tương tự

Thêm issue về Ruby

Nhận issue mới trong hộp thư của bạn

Bản tóm tắt ngắn những issue GitHub phù hợp với người mới.