From c8f7b119726290527903cbb312c832322002b0c9 Mon Sep 17 00:00:00 2001 From: Joshua Young Date: Sat, 4 Jul 2026 14:05:25 +1000 Subject: [PATCH] Expose CPU time in wall-mode Firefox output Measure CPU time via pthread_getcpuclockid on Linux and Mach thread_info on macOS, and surface it two ways: 1. Attached to every "Thread Running" marker interval as `cpu_time`. Hovering over the marker in the Firefox profiler shows how much CPU the thread actually consumed during that run, making preemption visible. 2. Emitted as per-sample threadCPUDelta on the samples table when the new `cpu_time:` option is set. The Firefox profiler renders this as a per-thread CPU utilization track. Opt-in because the profiler swaps the timeline's activity graph from category-coloured sample density to CPU utilization when the field is present. Fixes #29. --- README.md | 14 ++++ exe/vernier | 3 + ext/vernier/vernier.cc | 117 +++++++++++++++++++++++++++++----- lib/vernier/autorun.rb | 3 +- lib/vernier/middleware.rb | 3 +- lib/vernier/output/firefox.rb | 14 +++- test/firefox_test_helpers.rb | 5 ++ test/output/test_firefox.rb | 48 ++++++++++++++ test/test_time_collector.rb | 1 + 9 files changed, 188 insertions(+), 20 deletions(-) diff --git a/README.md b/README.md index b8cd321..47fe488 100644 --- a/README.md +++ b/README.md @@ -87,6 +87,19 @@ some_other_slow_method Vernier.stop_profile ``` +#### CPU utilization + +Passing `cpu_time: true` records CPU time consumed between each pair of +samples. The Firefox profiler renders this as a per-thread CPU utilization +track, which is useful for distinguishing time spent computing from time +spent waiting on I/O. + +```ruby +Vernier.profile(cpu_time: true, out: "time_profile.json") do + some_slow_method +end +``` + #### Rack middleware You can also use `Vernier::Middleware` to profile a Rack application: @@ -199,6 +212,7 @@ See [`examples/custom_hook.rb`](examples/custom_hook.rb) for a complete example. | `out` | N/A | File to write the profile to. | N/A (Auto-generated) | | `interval` | `vernier_interval` | Sampling interval (µs). Only in `:wall` mode. | `500` (`200`) | | `allocation_interval` | `vernier_allocation_interval` | Allocation sampling interval. Only in `:wall` mode. | `0` i.e. disabled (`200`) | +| `cpu_time` | `vernier_cpu_time` | Record per-sample CPU time. Only in `:wall` mode. | `false` (`false`) | | `gc` | N/A | Run full GC cycle before profiling. Only in `:retained` mode. | `true` (N/A) | | `metadata` | N/A | Metadata key-value pairs to include in the profile. | `{}` (N/A) | diff --git a/exe/vernier b/exe/vernier index adbffef..232a07d 100755 --- a/exe/vernier +++ b/exe/vernier @@ -37,6 +37,9 @@ FLAGS: o.on('--allocation-interval [ALLOCATIONS]', Integer, "allocation sampling interval (default 0 disabled)") do |i| options[:allocation_interval] = i end + o.on('--cpu-time', "record CPU time per sample") do + options[:cpu_time] = true + end o.on('--signal [NAME]', String, "specify a signal to start and stop the profiler") do |s| options[:signal] = s end diff --git a/ext/vernier/vernier.cc b/ext/vernier/vernier.cc index f9e0a15..e33c67a 100644 --- a/ext/vernier/vernier.cc +++ b/ext/vernier/vernier.cc @@ -14,6 +14,13 @@ #include #include +#include + +#if defined(__APPLE__) +#include +#include +#include +#endif #include "vernier.hh" #include "timestamp.hh" @@ -54,7 +61,7 @@ static VALUE rb_mVernierMarkerType; static VALUE rb_cVernierCollector; static VALUE rb_cTimeCollector; -static VALUE sym_state, sym_gc_by, sym_fiber_id; +static VALUE sym_state, sym_gc_by, sym_fiber_id, sym_cpu_time; static const char *gvl_event_name(rb_event_flag_t event) { switch (event) { @@ -157,6 +164,30 @@ static native_thread_id_t get_native_thread_id() { #endif } +// Returns cumulative CPU nanoseconds for a thread, or 0 if unavailable. +static uint64_t get_thread_cpu_time_ns(pthread_t pthread_id) { + if (!pthread_id) return 0; +#if defined(__APPLE__) + mach_port_t mach_thread = pthread_mach_thread_np(pthread_id); + if (!mach_thread) return 0; + thread_basic_info_data_t info; + mach_msg_type_number_t count = THREAD_BASIC_INFO_COUNT; + kern_return_t kr = thread_info(mach_thread, THREAD_BASIC_INFO, (thread_info_t)&info, &count); + if (kr != KERN_SUCCESS) return 0; + uint64_t ns = (uint64_t)info.user_time.seconds * 1000000000ULL + + (uint64_t)info.user_time.microseconds * 1000ULL + + (uint64_t)info.system_time.seconds * 1000000000ULL + + (uint64_t)info.system_time.microseconds * 1000ULL; + return ns; +#else + clockid_t clockid; + if (pthread_getcpuclockid(pthread_id, &clockid) != 0) return 0; + struct timespec ts; + if (clock_gettime(clockid, &ts) != 0) return 0; + return (uint64_t)ts.tv_sec * 1000000000ULL + (uint64_t)ts.tv_nsec; +#endif +} + union MarkerInfo { struct { VALUE gc_by; @@ -165,6 +196,9 @@ union MarkerInfo { struct { VALUE fiber_id; } fiber_data; + struct { + uint64_t cpu_time_ns; + } thread_running_data; }; #define EACH_MARKER(XX) \ @@ -237,6 +271,11 @@ class Marker { record[5] = hash; rb_hash_aset(hash, sym_fiber_id, extra_info.fiber_data.fiber_id); + } else if (type == Marker::MARKER_THREAD_RUNNING && extra_info.thread_running_data.cpu_time_ns) { + VALUE hash = rb_hash_new(); + record[5] = hash; + + rb_hash_aset(hash, sym_cpu_time, ULL2NUM(extra_info.thread_running_data.cpu_time_ns / 1000)); } return rb_ary_new_from_values(6, record); } @@ -247,10 +286,10 @@ class MarkerTable { std::mutex mutex; std::vector list; - void record_interval(Marker::Type type, TimeStamp from, TimeStamp to, int stack_index = -1) { + void record_interval(Marker::Type type, TimeStamp from, TimeStamp to, int stack_index = -1, MarkerInfo extra_info = {}) { const std::lock_guard lock(mutex); - list.push_back({ type, Marker::INTERVAL, from, to, stack_index }); + list.push_back({ type, Marker::INTERVAL, from, to, stack_index, extra_info }); } void record(Marker::Type type, int stack_index = -1, MarkerInfo extra_info = {}) { @@ -361,6 +400,7 @@ class SampleList { std::vector timestamps; std::vector categories; std::vector weights; + std::vector cpu_delta_ns; size_t size() { return stacks.size(); @@ -370,7 +410,7 @@ class SampleList { return size() == 0; } - void record_sample(int stack_index, TimeStamp time, Category category) { + void record_sample(int stack_index, TimeStamp time, Category category, uint64_t delta_ns = 0) { // FIXME: probably better to avoid generating -1 higher up. // Currently this happens when we measure an empty stack. Ideally we would have a better representation if (stack_index < 0) @@ -380,15 +420,17 @@ class SampleList { categories.back() == category) { // We don't compare timestamps for de-duplication weights.back() += 1; + cpu_delta_ns.back() += delta_ns; } else { stacks.push_back(stack_index); timestamps.push_back(time); categories.push_back(category); weights.push_back(1); + cpu_delta_ns.push_back(delta_ns); } } - void write_result(VALUE result) const { + void write_result(VALUE result, bool record_cpu_time) const { VALUE samples = rb_ary_new(); rb_hash_aset(result, sym("samples"), samples); for (auto& stack_index: this->stacks) { @@ -412,6 +454,14 @@ class SampleList { for (auto& cat: this->categories) { rb_ary_push(sample_categories, INT2NUM(cat)); } + + if (record_cpu_time) { + VALUE cpu_deltas = rb_ary_new(); + rb_hash_aset(result, sym("cpu_delta_ns"), cpu_deltas); + for (auto& d: this->cpu_delta_ns) { + rb_ary_push(cpu_deltas, ULL2NUM(d)); + } + } } }; @@ -442,6 +492,9 @@ class Thread { int stack_on_suspend_idx; SampleTranslator translator; + uint64_t last_cpu_ns = 0; // baseline for per-sample deltas + uint64_t running_entry_cpu_ns = 0; // baseline for RUNNING-interval deltas + unique_ptr markers; // FIXME: don't use pthread at start @@ -477,6 +530,16 @@ class Thread { markers->record(Marker::Type::MARKER_FIBER_SWITCH, stack_idx, { .fiber_data = { .fiber_id = fiber_id } }); } + MarkerInfo running_cpu_extra_info() const { + MarkerInfo info = {}; + if (state != State::RUNNING || !running_entry_cpu_ns) return info; + uint64_t now_cpu = get_thread_cpu_time_ns(pthread_id); + if (now_cpu > running_entry_cpu_ns) { + info.thread_running_data.cpu_time_ns = now_cpu - running_entry_cpu_ns; + } + return info; + } + void set_state(State new_state, bool current = true) { if (state == Thread::State::STOPPED) { return; @@ -505,6 +568,12 @@ class Thread { pthread_id = pthread_self(); native_tid = get_native_thread_id(); + // Rebase both CPU baselines so per-sample and + // RUNNING-interval deltas ignore time spent while another + // thread held the GVL. + last_cpu_ns = get_thread_cpu_time_ns(pthread_id); + running_entry_cpu_ns = last_cpu_ns; + // If the GVL is immediately ready, and we measure no times // stalled, skip emitting the interval. if (from != now) { @@ -524,18 +593,18 @@ class Thread { markers->record_interval(Marker::Type::MARKER_THREAD_SUSPENDED, from, now, stack_on_suspend_idx); } else if (state == State::RUNNING) { - markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now); + markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now, -1, running_cpu_extra_info()); } break; case State::SUSPENDED: // We can go from RUNNING or STARTED to SUSPENDED assert(state == State::INITIAL || state == State::RUNNING || state == State::STARTED || state == State::SUSPENDED); - markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now); + markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now, -1, running_cpu_extra_info()); break; case State::STOPPED: // We can go from RUNNING or STARTED or SUSPENDED to STOPPED assert(state == State::INITIAL || state == State::RUNNING || state == State::STARTED || state == State::SUSPENDED); - markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now); + markers->record_interval(Marker::Type::MARKER_THREAD_RUNNING, from, now, -1, running_cpu_extra_info()); markers->record(Marker::Type::MARKER_GVL_THREAD_EXITED); stopped_at = now; @@ -840,6 +909,7 @@ class TimeCollector : public BaseCollector { TimeStamp interval; unsigned int allocation_interval; unsigned int allocation_tick = 0; + bool record_cpu_time; VALUE tp_newobj = Qnil; @@ -854,7 +924,7 @@ class TimeCollector : public BaseCollector { TimeCollectorThread collector_thread; public: - TimeCollector(VALUE stack_table, TimeStamp interval, unsigned int allocation_interval) : BaseCollector(stack_table), interval(interval), allocation_interval(allocation_interval), threads(*get_stack_table(stack_table)), collector_thread(*this, interval) { + TimeCollector(VALUE stack_table, TimeStamp interval, unsigned int allocation_interval, bool record_cpu_time) : BaseCollector(stack_table), interval(interval), allocation_interval(allocation_interval), record_cpu_time(record_cpu_time), threads(*get_stack_table(stack_table)), collector_thread(*this, interval) { } void record_newobj(VALUE obj) { @@ -892,22 +962,34 @@ class TimeCollector : public BaseCollector { BaseCollector::write_meta(meta, result); rb_hash_aset(meta, sym("interval"), ULL2NUM(interval.microseconds())); rb_hash_aset(meta, sym("allocation_interval"), ULL2NUM(allocation_interval)); - + rb_hash_aset(meta, sym("cpu_time"), record_cpu_time ? Qtrue : Qfalse); } private: - void record_sample(const RawSample &sample, TimeStamp time, Thread &thread, Category category) { + void record_sample(const RawSample &sample, TimeStamp time, Thread &thread, Category category, uint64_t cpu_delta_ns = 0) { if (!sample.empty()) { int stack_index = thread.translator.translate(*stack_table, sample); thread.samples.record_sample( stack_index, time, - category + category, + cpu_delta_ns ); } } + // Advances the CPU baseline and returns delta ns since the previous call. + uint64_t take_cpu_delta_ns(Thread &thread) { + uint64_t now = get_thread_cpu_time_ns(thread.pthread_id); + if (now == 0) return 0; + uint64_t delta = (thread.last_cpu_ns && now > thread.last_cpu_ns) + ? now - thread.last_cpu_ns + : 0; + thread.last_cpu_ns = now; + return delta; + } + void run_iteration() { TimeStamp sample_start = TimeStamp::Now(); @@ -931,7 +1013,8 @@ class TimeCollector : public BaseCollector { } else if (sample.sample.empty()) { // fprintf(stderr, "skipping GC sample\n"); } else { - record_sample(sample.sample, sample_start, thread, CATEGORY_NORMAL); + uint64_t cpu_delta = record_cpu_time ? take_cpu_delta_ns(thread) : 0; + record_sample(sample.sample, sample_start, thread, CATEGORY_NORMAL, cpu_delta); } } else if (thread.state == Thread::State::SUSPENDED) { thread.samples.record_sample( @@ -1101,7 +1184,7 @@ class TimeCollector : public BaseCollector { for (const auto& thread: this->threads.list) { VALUE hash = rb_hash_new(); - thread->samples.write_result(hash); + thread->samples.write_result(hash, record_cpu_time); thread->allocation_samples.write_result(hash); rb_hash_aset(hash, sym("markers"), thread->markers->to_array()); rb_hash_aset(hash, sym("tid"), ULL2NUM(thread->native_tid)); @@ -1207,7 +1290,10 @@ static VALUE collector_new(VALUE self, VALUE mode, VALUE options) { } else { allocation_interval = NUM2UINT(allocation_intervalv); } - collector = new TimeCollector(stack_table, interval, allocation_interval); + + bool record_cpu_time = RTEST(rb_hash_aref(options, sym("cpu_time"))); + + collector = new TimeCollector(stack_table, interval, allocation_interval, record_cpu_time); } else { rb_raise(rb_eArgError, "invalid mode"); } @@ -1240,6 +1326,7 @@ Init_vernier(void) sym_state = sym("state"); sym_gc_by = sym("gc_by"); sym_fiber_id = sym("fiber_id"); + sym_cpu_time = sym("cpu_time"); rb_gc_latest_gc_info(sym_state); // HACK: needs to be warmed so that it can be called during GC rb_mVernier = rb_define_module("Vernier"); diff --git a/lib/vernier/autorun.rb b/lib/vernier/autorun.rb index 7b262f3..6d1f4eb 100644 --- a/lib/vernier/autorun.rb +++ b/lib/vernier/autorun.rb @@ -19,6 +19,7 @@ class << self def self.start interval = options.fetch(:interval, 500).to_i allocation_interval = options.fetch(:allocation_interval, 0).to_i + cpu_time = options[:cpu_time] == "true" hooks = options.fetch(:hooks, "").split(",") metadata = if options[:metadata] JSON.parse(@options[:metadata].unpack1("m")).to_h { |k, v| [k.to_sym, v] } @@ -28,7 +29,7 @@ def self.start STDERR.puts("starting profiler with interval #{interval} and allocation interval #{allocation_interval}") - @collector = Vernier::Collector.new(:wall, interval:, allocation_interval:, hooks:, metadata:) + @collector = Vernier::Collector.new(:wall, interval:, allocation_interval:, cpu_time:, hooks:, metadata:) @collector.start end diff --git a/lib/vernier/middleware.rb b/lib/vernier/middleware.rb index 967707c..3447877 100644 --- a/lib/vernier/middleware.rb +++ b/lib/vernier/middleware.rb @@ -19,8 +19,9 @@ def call(env) interval = request.GET.fetch("vernier_interval", 200).to_i allocation_interval = request.GET.fetch("vernier_allocation_interval", 200).to_i + cpu_time = request.GET["vernier_cpu_time"] == "true" - result = Vernier.trace(interval:, allocation_interval:, hooks: HOOKS) do + result = Vernier.trace(interval:, allocation_interval:, cpu_time:, hooks: HOOKS) do @app.call(env) end body = result.to_firefox(gzip: true) diff --git a/lib/vernier/output/firefox.rb b/lib/vernier/output/firefox.rb index 5161e6e..a864838 100644 --- a/lib/vernier/output/firefox.rb +++ b/lib/vernier/output/firefox.rb @@ -214,7 +214,8 @@ def marker_schema { label: "Description", value: "The thread has acquired the GVL and is executing" - } + }, + { key: "cpu_time", label: "CPU time", format: "microseconds" } ] }, { @@ -274,7 +275,7 @@ class Thread attr_reader :profile, :is_start - def initialize(ruby_thread_id, profile, categorizer, name:, tid:, samples:, weights:, timestamps: nil, sample_categories: nil, markers:, started_at:, stopped_at: nil, allocations: nil, is_main: nil, is_start: nil) + def initialize(ruby_thread_id, profile, categorizer, name:, tid:, samples:, weights:, timestamps: nil, sample_categories: nil, cpu_delta_ns: nil, markers:, started_at:, stopped_at: nil, allocations: nil, is_main: nil, is_start: nil) @ruby_thread_id = ruby_thread_id @profile = profile @categorizer = categorizer @@ -304,6 +305,7 @@ def initialize(ruby_thread_id, profile, categorizer, name:, tid:, samples:, weig timestamps ||= [0] * samples.size @weights, @timestamps = weights, timestamps @sample_categories = sample_categories || ([0] * samples.size) + @cpu_delta_ns = cpu_delta_ns @markers = markers.map do |marker| if stack_idx = marker[5]&.dig(:cause, :stack) marker = marker.dup @@ -539,13 +541,19 @@ def samples_table end end - { + table = { stack: samples, time: times, weight: weights, weightType: profile.meta[:mode] == :retained ? "bytes" : "samples", length: samples.length } + + if @cpu_delta_ns + table[:threadCPUDelta] = @cpu_delta_ns.map { |ns| ns / 1_000 } + end + + table end def stack_table diff --git a/test/firefox_test_helpers.rb b/test/firefox_test_helpers.rb index 093be28..88f20ac 100644 --- a/test/firefox_test_helpers.rb +++ b/test/firefox_test_helpers.rb @@ -134,6 +134,11 @@ def assert_valid_firefox_profile(profile) assert_operator samples["stack"].max || -1, :<, thread["stackTable"]["length"] + if cpu_delta = samples["threadCPUDelta"] + assert_equal samples["length"], cpu_delta.size + cpu_delta.each { |us| assert_operator us, :>=, 0 } + end + if allocations = thread["jsAllocations"] assert_equal allocations["length"], allocations["stack"].size assert_equal allocations["length"], allocations["weight"].size diff --git a/test/output/test_firefox.rb b/test/output/test_firefox.rb index 178542b..57e1b8a 100644 --- a/test/output/test_firefox.rb +++ b/test/output/test_firefox.rb @@ -59,6 +59,31 @@ def test_gc_events_have_duration assert_includes names, "GC pause" end + def test_thread_running_markers_have_cpu_time + result = Vernier.trace do + target = Process.clock_gettime(Process::CLOCK_MONOTONIC) + 0.02 + while Process.clock_gettime(Process::CLOCK_MONOTONIC) < target + end + # force a RUNNING → SUSPENDED transition so a Thread Running marker is emitted + sleep 0.01 + end + output = Vernier::Output::Firefox.new(result).output + assert_valid_firefox_profile(output) + + data = JSON.parse(output) + main_thread = data["threads"].find { _1["isMainThread"] } + markers = main_thread["markers"] + + cpu_times = markers["length"].times.filter_map do |i| + name = main_thread["stringArray"][markers["name"][i]] + next unless name == "Thread Running" + markers["data"][i]&.dig("cpu_time") + end + + refute_empty cpu_times + assert cpu_times.any? { _1 > 0 } + end + def test_retained_firefox_output retained = [] @@ -230,6 +255,29 @@ def test_allocation_samples assert_valid_firefox_profile(output) end + def test_cpu_time_firefox_output + result = Vernier.trace(cpu_time: true) do + sleep 0.01 + target = Process.clock_gettime(Process::CLOCK_MONOTONIC) + 0.01 + while Process.clock_gettime(Process::CLOCK_MONOTONIC) < target + end + end + + output = Vernier::Output::Firefox.new(result).output + assert_valid_firefox_profile(output) + + data = JSON.parse(output) + assert_equal "µs", data.dig("meta", "sampleUnits", "threadCPUDelta") + + main_thread = data["threads"].find { _1["isMainThread"] } + samples = main_thread["samples"] + cpu_delta = samples["threadCPUDelta"] + + refute_nil cpu_delta + assert_equal samples["length"], cpu_delta.size + assert_operator cpu_delta.sum, :>, 0 + end + def test_profile_with_various_encodings result = Vernier.trace(mode: :custom) do |profiler| sample = -> { profiler.sample } diff --git a/test/test_time_collector.rb b/test/test_time_collector.rb index 9e82422..76498ec 100644 --- a/test/test_time_collector.rb +++ b/test/test_time_collector.rb @@ -286,6 +286,7 @@ def test_includes_options_in_result_meta assert_equal SAMPLE_SCALE_INTERVAL, result.meta[:interval] assert_equal SAMPLE_SCALE_ALLOCATIONS, result.meta[:allocation_interval] assert_equal false, result.meta[:gc] + assert_equal false, result.meta[:cpu_time] assert_equal ({ key1: "val1", key2: "val2" }), result.meta[:user_metadata] end