Skip to content

Commit

Permalink
Added: CThread extension for profiling.
Browse files Browse the repository at this point in the history
  • Loading branch information
delner committed Sep 9, 2020
1 parent a4bf5f8 commit 685b923
Show file tree
Hide file tree
Showing 11 changed files with 461 additions and 8 deletions.
1 change: 1 addition & 0 deletions ddtrace.gemspec
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ Gem::Specification.new do |spec|

# Optional extensions
spec.add_development_dependency 'dogstatsd-ruby', '>= 3.3.0'
spec.add_development_dependency 'ffi', '~> 1.0'
spec.add_development_dependency 'opentracing', '>= 0.4.1'

if RUBY_PLATFORM != 'java'
Expand Down
9 changes: 9 additions & 0 deletions lib/ddtrace/profiling.rb
Original file line number Diff line number Diff line change
Expand Up @@ -3,12 +3,20 @@ module Datadog
module Profiling
module_function

FFI_MINIMUM_VERSION = Gem::Version.new('1.0')
GOOGLE_PROTOBUF_MINIMUM_VERSION = Gem::Version.new('3.0')

def supported?
google_protobuf_supported?
end

def native_cpu_time_supported?
RUBY_PLATFORM != 'java' \
&& Gem::Version.new(RUBY_VERSION) >= Gem::Version.new('2.1') \
&& !Gem.loaded_specs['ffi'].nil? \
&& Gem.loaded_specs['ffi'].version >= FFI_MINIMUM_VERSION
end

def google_protobuf_supported?
RUBY_PLATFORM != 'java' \
&& !Gem.loaded_specs['google-protobuf'].nil? \
Expand All @@ -20,6 +28,7 @@ def load_profiling
require 'ddtrace/profiling/exporter'
require 'ddtrace/profiling/recorder'
require 'ddtrace/profiling/scheduler'
require 'ddtrace/profiling/tasks/setup'
require 'ddtrace/profiling/transport/io'

require 'ddtrace/profiling/pprof/pprof_pb' if google_protobuf_supported?
Expand Down
88 changes: 88 additions & 0 deletions lib/ddtrace/profiling/ext/thread.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
require 'ffi'

module Datadog
module Profiling
module Ext
# C-struct for retrieving clock ID from pthread
class CClockId < FFI::Struct
layout :value, :int
end

# Extensions for pthread-backed Ruby threads, to retrieve
# the thread ID, clock ID, and CPU time.
module CThread
extend FFI::Library
ffi_lib 'ruby', 'pthread'
attach_function :rb_nativethread_self, [], :ulong
attach_function :pthread_getcpuclockid, [:ulong, CClockId], :int

def self.prepended(base)
# Be sure to update the current thread too; as it wouldn't have been set.
::Thread.current.send(:update_native_ids)
end

attr_reader \
:native_thread_id

def initialize(*args)
@pid = Process.pid
@native_thread_id = nil
@clock_id = nil

# Wrap the work block with our own
# so we can retrieve the native thread ID within the thread's context.
wrapped_block = proc do |*t_args|
# Set native thread ID & clock ID
update_native_ids
yield(*t_args)
end

super(*args, &wrapped_block)
end

def clock_id
update_native_ids if forked?
@clock_id ||= nil
end

def cpu_time(unit = :float_second)
return unless clock_id && Process.respond_to?(:clock_gettime)
Process.clock_gettime(clock_id, unit)
end

private

# Retrieves number of classes from runtime
def forked?
Process.pid != (@pid ||= nil)
end

def update_native_ids
@pid = Process.pid
@native_thread_id = get_native_thread_id
@clock_id = get_clock_id(@native_thread_id)
end

def get_native_thread_id
# Only run if invoked from same thread, otherwise
# it will receive incorrect thread ID.
return unless ::Thread.current == self

# NOTE: Only returns thread ID for thread that evaluates this call.
# a.k.a. evaluating `thread_a.get_native_thread_id` from within
# `thread_b` will return `thread_b`'s thread ID, not `thread_a`'s.
rb_nativethread_self
end

def get_clock_id(pthread_id)
return unless pthread_id && alive?

# Build a struct, pass it to Pthread's getcpuclockid function.
clock = CClockId.new
clock[:value] = 0
pthread_getcpuclockid(pthread_id, clock).zero? ? clock[:value] : nil
end
end
end
end
end
2 changes: 1 addition & 1 deletion lib/ddtrace/profiling/pprof/converter.rb
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ def sample_value_index(type)
def build_sample_values(stack_sample)
# Build a value array that matches the length of the sample types
# Populate all values with "no value" by default
Array.new(@sample_type_mappings.length, Ext::Profiling::Pprof::SAMPLE_VALUE_NO_VALUE)
Array.new(@sample_type_mappings.length, Datadog::Ext::Profiling::Pprof::SAMPLE_VALUE_NO_VALUE)
end

# Represents a grouped event
Expand Down
6 changes: 3 additions & 3 deletions lib/ddtrace/profiling/pprof/stack_sample.rb
Original file line number Diff line number Diff line change
Expand Up @@ -10,8 +10,8 @@ module Pprof
class StackSample < Converter
SAMPLE_TYPES = {
wall_time_ns: [
Ext::Profiling::Pprof::VALUE_TYPE_WALL,
Ext::Profiling::Pprof::VALUE_UNIT_NANOSECONDS
Datadog::Ext::Profiling::Pprof::VALUE_TYPE_WALL,
Datadog::Ext::Profiling::Pprof::VALUE_UNIT_NANOSECONDS
]
}.freeze

Expand Down Expand Up @@ -63,7 +63,7 @@ def build_sample_values(stack_sample)
def build_sample_labels(stack_sample)
[
Perftools::Profiles::Label.new(
key: builder.string_table.fetch(Ext::Profiling::Pprof::LABEL_KEY_THREAD_ID),
key: builder.string_table.fetch(Datadog::Ext::Profiling::Pprof::LABEL_KEY_THREAD_ID),
str: builder.string_table.fetch(stack_sample.thread_id.to_s)
)
]
Expand Down
9 changes: 7 additions & 2 deletions lib/ddtrace/profiling/preload.rb
Original file line number Diff line number Diff line change
@@ -1,2 +1,7 @@
require 'ddtrace/profiling/tasks/setup'
Datadog::Profiling::Tasks::Setup.new.execute
require 'ddtrace/profiling'

if Datadog::Profiling.supported? && Datadog::Profiling.native_cpu_time_supported?
Datadog::Profiling::Tasks::Setup.new.run
else
puts '[DDTRACE] Profiling not supported; skipping preload.'
end
9 changes: 7 additions & 2 deletions lib/ddtrace/profiling/tasks/setup.rb
Original file line number Diff line number Diff line change
@@ -1,9 +1,14 @@
module Datadog
module Profiling
module Tasks
# Sets up profiling for the application
class Setup
def execute
# TODO
def run
# Activate CPU timings
require 'ddtrace/profiling/ext/thread'
::Thread.send(:prepend, Profiling::Ext::CThread)
rescue StandardError, ScriptError => e
puts "[DDTRACE] CPU profiling unavailable. Cause: #{e.message} Location: #{e.backtrace.first}"
end
end
end
Expand Down
162 changes: 162 additions & 0 deletions spec/ddtrace/profiling/ext/thread_spec.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,162 @@
require 'spec_helper'
require 'ddtrace/profiling'

if Datadog::Profiling.native_cpu_time_supported?
require 'ddtrace/profiling/ext/thread'

RSpec.describe Datadog::Profiling::Ext::CThread do
subject(:thread) do
thread_class.new(&block).tap do
# Give thread a chance to start,
# which will set native IDs.
@thread_started = true
sleep(0.05)
end
end

let(:block) { proc { loop { sleep(1) } } }

let(:thread_class) do
Thread.send(:prepend, described_class)
Thread
end

# Leave Thread class in a clean state before and after tests
around do |example|
expect(::Thread.ancestors).to_not include(described_class)
unmodified_class = ::Thread.dup

example.run

Object.send(:remove_const, :Thread)
Object.const_set('Thread', unmodified_class)
end

# Kill any spawned threads
after { thread.kill if instance_variable_defined?(:@thread_started) && @thread_started }

describe 'prepend' do
it 'sets native thread IDs on current thread' do
expect(thread_class.current).to have_attributes(
clock_id: kind_of(Integer),
native_thread_id: kind_of(Integer),
cpu_time: kind_of(Float)
)
end
end

describe '::new' do
it 'has native thread IDs available' do
is_expected.to have_attributes(
clock_id: kind_of(Integer),
native_thread_id: kind_of(Integer),
cpu_time: kind_of(Float)
)
end
end

describe '#native_thread_id' do
subject(:native_thread_id) { thread.native_thread_id }

it { is_expected.to be_a_kind_of(Integer) }

context 'main thread' do
context 'when forked' do
it 'returns a new native thread ID' do
# Get main thread clock ID
original_native_thread_id = thread_class.current.native_thread_id

expect_in_fork do
# Expect main thread native ID to not change
expect(thread_class.current.native_thread_id).to be_a_kind_of(Integer)
expect(thread_class.current.native_thread_id).to eq(original_native_thread_id)
end
end
end
end
end

describe '#clock_id' do
subject(:clock_id) { thread.clock_id }

it { is_expected.to be_a_kind_of(Integer) }

context 'main thread' do
context 'when forked' do
it 'returns a new clock ID' do
# Get main thread clock ID
original_clock_id = thread_class.current.clock_id

expect_in_fork do
# Expect main thread clock ID to change (to match fork's main thread)
expect(thread_class.current.clock_id).to be_a_kind_of(Integer)
expect(thread_class.current.clock_id).to_not eq(original_clock_id)
end
end
end
end
end

describe '#cpu_time' do
subject(:cpu_time) { thread.cpu_time }

context 'when clock ID' do
before { allow(thread).to receive(:clock_id).and_return(clock_id) }

context 'is not available' do
let(:clock_id) { nil }
it { is_expected.to be nil }
end

context 'is available' do
let(:clock_id) { double('clock ID') }

if Process.respond_to?(:clock_gettime)
let(:cpu_time_measurement) { double('cpu time measurement') }

context 'when not given a unit' do
it 'gets time in CPU seconds' do
expect(Process)
.to receive(:clock_gettime)
.with(clock_id, :float_second)
.and_return(cpu_time_measurement)

is_expected.to be cpu_time_measurement
end
end

context 'given a unit' do
subject(:cpu_time) { thread.cpu_time(unit) }
let(:unit) { double('unit') }

it 'gets time in specified unit' do
expect(Process)
.to receive(:clock_gettime)
.with(clock_id, unit)
.and_return(cpu_time_measurement)

is_expected.to be cpu_time_measurement
end
end
else
context 'but #clock_gettime is not' do
it { is_expected.to be nil }
end
end
end
end

context 'main thread' do
context 'when forked' do
it 'returns a CPU time' do
expect(thread_class.current.cpu_time).to be_a_kind_of(Float)

expect_in_fork do
expect(thread_class.current.cpu_time).to be_a_kind_of(Float)
end
end
end
end
end
end
end
42 changes: 42 additions & 0 deletions spec/ddtrace/profiling/preload_spec.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
require 'spec_helper'
require 'ddtrace/profiling'

RSpec.describe 'Profiling preloading' do
subject(:preload) { load 'ddtrace/profiling/preload.rb' }

shared_examples_for 'skipped preloading' do
it 'displays a warning' do
expect(STDOUT).to receive(:puts) do |message|
expect(message).to include('Profiling not supported')
end

preload
end
end

context 'when profiling is not supported' do
before { allow(Datadog::Profiling).to receive(:supported?).and_return(false) }
it_behaves_like 'skipped preloading'
end

context 'when native CPU time is not supported' do
before { allow(Datadog::Profiling).to receive(:native_cpu_time_supported?).and_return(false) }
it_behaves_like 'skipped preloading'
end

context 'when profiling and native CPU time is supported' do
let(:setup_task) { instance_double(Datadog::Profiling::Tasks::Setup) }

before do
allow(Datadog::Profiling).to receive(:supported?).and_return(true)
allow(Datadog::Profiling).to receive(:native_cpu_time_supported?).and_return(true)
allow(Datadog::Profiling::Tasks::Setup).to receive(:new).and_return(setup_task)
end

it 'preloads without warning' do
expect(setup_task).to receive(:run)
expect(STDOUT).to_not receive(:puts)
preload
end
end
end
Loading

0 comments on commit 685b923

Please sign in to comment.