Skip to content

Commit

Permalink
fix!: Replace Time.now with Process.clock_gettime (#717)
Browse files Browse the repository at this point in the history
* fix!: Replace Time.now with Process.clock_gettime

* fix silly mistake

* Remove some noise and unnecessary supers

* fix: replace Time with Integer nanoseconds

* fix: tests

* fix: tests
  • Loading branch information
fbogsany authored Apr 28, 2021
1 parent ed62ab2 commit 50ce54b
Show file tree
Hide file tree
Showing 26 changed files with 117 additions and 178 deletions.
4 changes: 4 additions & 0 deletions common/lib/opentelemetry/common/test_helpers.rb
Original file line number Diff line number Diff line change
Expand Up @@ -13,3 +13,7 @@ def with_env(new_env)
env_to_reset.each_pair { |k, v| ENV[k] = v }
keys_to_delete.each { |k| ENV.delete(k) }
end

def exportable_timestamp(time = Time.now)
(time.to_r * 1_000_000_000).to_i
end
18 changes: 17 additions & 1 deletion common/lib/opentelemetry/common/utilities.rb
Original file line number Diff line number Diff line change
Expand Up @@ -14,13 +14,29 @@ module Utilities

# Returns nil if timeout is nil, 0 if timeout has expired,
# or the remaining (positive) time left in seconds.
#
# @param [Numeric] timeout The timeout in seconds. May be nil.
# @param [Numeric] start_time Start time for timeout returned
# by {timeout_timestamp}.
#
# @return [Numeric] remaining (positive) time left in seconds.
# May be nil.
def maybe_timeout(timeout, start_time)
return nil if timeout.nil?

timeout -= (Time.now - start_time)
timeout -= (timeout_timestamp - start_time)
timeout.positive? ? timeout : 0
end

# Returns a timestamp suitable to pass as the start_time
# argument to {maybe_timeout}. This has no meaning outside
# of the current process.
#
# @return [Numeric]
def timeout_timestamp
Process.clock_gettime(Process::CLOCK_MONOTONIC)
end

# Encodes a string in utf8
#
# @param [String] string The string to be utf8 encoded
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ def initialize(host: ENV.fetch('OTEL_EXPORTER_JAEGER_AGENT_HOST', 'localhost'),
def export(span_data, timeout: nil)
return FAILURE if @shutdown

start_time = Time.now
start_time = OpenTelemetry::Common::Utilities.timeout_timestamp
encoded_batches(span_data) do |batch|
return FAILURE if @shutdown || OpenTelemetry::Common::Utilities.maybe_timeout(timeout, start_time)&.zero?

Expand Down
6 changes: 3 additions & 3 deletions exporter/jaeger/lib/opentelemetry/exporter/jaeger/encoder.rb
Original file line number Diff line number Diff line change
Expand Up @@ -65,8 +65,8 @@ def encoded_tag(key, value)
end

def encoded_span(span_data) # rubocop:disable Metrics/AbcSize
start_time = (span_data.start_timestamp.to_f * 1_000_000).to_i
duration = (span_data.end_timestamp.to_f * 1_000_000).to_i - start_time
start_time = span_data.start_timestamp / 1_000
duration = span_data.end_timestamp / 1_000 - start_time

Thrift::Span.new(
'traceIdLow' => int64(span_data.trace_id[8, 8]),
Expand Down Expand Up @@ -102,7 +102,7 @@ def encoded_kind(kind)
def encoded_logs(events)
events&.map do |event|
Thrift::Log.new(
'timestamp' => (event.timestamp.to_f * 1_000_000).to_i,
'timestamp' => event.timestamp / 1_000,
'fields' => encoded_tags(event.attributes) + encoded_tags('name' => event.name)
)
end
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,7 @@
attributes = { 'akey' => 'avalue' }
events = [
OpenTelemetry::SDK::Trace::Event.new(
name: 'event', attributes: { 'ekey' => 'evalue' }
'event', { 'ekey' => 'evalue' }, exportable_timestamp
)
]
span_data = create_span_data(attributes: attributes, events: events)
Expand All @@ -66,7 +66,7 @@
attributes = { 'akey' => ['avalue'] }
events = [
OpenTelemetry::SDK::Trace::Event.new(
name: 'event', attributes: { 'ekey' => ['evalue'] }
'event', { 'ekey' => ['evalue'] }, exportable_timestamp
)
]
span_data = create_span_data(attributes: attributes, events: events)
Expand Down Expand Up @@ -125,8 +125,8 @@ def create_span_data(status: nil, kind: nil, attributes: nil, events: nil, links
0,
0,
0,
Time.now,
Time.now,
exportable_timestamp,
exportable_timestamp,
attributes,
links,
events,
Expand Down
4 changes: 2 additions & 2 deletions exporter/jaeger/test/test_helper.rb
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@
require 'webmock/minitest'

def create_span_data(name: '', kind: nil, status: nil, parent_span_id: OpenTelemetry::Trace::INVALID_SPAN_ID,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: Time.now,
end_timestamp: Time.now, attributes: nil, links: nil, events: nil, resource: nil, instrumentation_library: nil,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: exportable_timestamp,
end_timestamp: exportable_timestamp, attributes: nil, links: nil, events: nil, resource: nil, instrumentation_library: nil,
span_id: OpenTelemetry::Trace.generate_span_id, trace_id: OpenTelemetry::Trace.generate_trace_id,
trace_flags: OpenTelemetry::Trace::TraceFlags::DEFAULT, tracestate: nil)
OpenTelemetry::SDK::Trace::SpanData.new(name, kind, status, parent_span_id, total_recorded_attributes,
Expand Down
12 changes: 4 additions & 8 deletions exporter/otlp/lib/opentelemetry/exporter/otlp/exporter.rb
Original file line number Diff line number Diff line change
Expand Up @@ -139,7 +139,7 @@ def around_request
def send_bytes(bytes, timeout:) # rubocop:disable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/MethodLength, Metrics/PerceivedComplexity
retry_count = 0
timeout ||= @timeout
start_time = Time.now
start_time = OpenTelemetry::Common::Utilities.timeout_timestamp
around_request do # rubocop:disable Metrics/BlockLength
request = Net::HTTP::Post.new(@path)
request.body = if @compression == 'gzip'
Expand Down Expand Up @@ -277,13 +277,13 @@ def as_otlp_span(span_data) # rubocop:disable Metrics/AbcSize, Metrics/MethodLen
parent_span_id: span_data.parent_span_id == OpenTelemetry::Trace::INVALID_SPAN_ID ? nil : span_data.parent_span_id,
name: span_data.name,
kind: as_otlp_span_kind(span_data.kind),
start_time_unix_nano: as_otlp_timestamp(span_data.start_timestamp),
end_time_unix_nano: as_otlp_timestamp(span_data.end_timestamp),
start_time_unix_nano: span_data.start_timestamp,
end_time_unix_nano: span_data.end_timestamp,
attributes: span_data.attributes&.map { |k, v| as_otlp_key_value(k, v) },
dropped_attributes_count: span_data.total_recorded_attributes - span_data.attributes&.size.to_i,
events: span_data.events&.map do |event|
Opentelemetry::Proto::Trace::V1::Span::Event.new(
time_unix_nano: as_otlp_timestamp(event.timestamp),
time_unix_nano: event.timestamp,
name: event.name,
attributes: event.attributes&.map { |k, v| as_otlp_key_value(k, v) }
# TODO: track dropped_attributes_count in Span#append_event
Expand All @@ -310,10 +310,6 @@ def as_otlp_span(span_data) # rubocop:disable Metrics/AbcSize, Metrics/MethodLen
)
end

def as_otlp_timestamp(timestamp)
(timestamp.to_r * 1_000_000_000).to_i
end

def as_otlp_span_kind(kind)
case kind
when :internal then Opentelemetry::Proto::Trace::V1::Span::SpanKind::INTERNAL
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -373,8 +373,8 @@ def with_ids(trace_id, span_id)
end

def create_span_data(name: '', kind: nil, status: nil, parent_span_id: OpenTelemetry::Trace::INVALID_SPAN_ID,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: Time.now,
end_timestamp: Time.now, attributes: nil, links: nil, events: nil, resource: nil,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: exportable_timestamp,
end_timestamp: exportable_timestamp, attributes: nil, links: nil, events: nil, resource: nil,
instrumentation_library: OpenTelemetry::SDK::InstrumentationLibrary.new('', 'v0.0.1'),
span_id: OpenTelemetry::Trace.generate_span_id, trace_id: OpenTelemetry::Trace.generate_trace_id,
trace_flags: OpenTelemetry::Trace::TraceFlags::DEFAULT, tracestate: nil)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -132,7 +132,7 @@ def valid_headers?(headers)
def send_spans(zipkin_spans, timeout: nil) # rubocop:disable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/MethodLength
retry_count = 0
timeout ||= @timeout
start_time = Time.now
start_time = OpenTelemetry::Common::Utilities.timeout_timestamp
around_request do # rubocop:disable Metrics/BlockLength
request = Net::HTTP::Post.new(@path)
request.body = JSON.generate(zipkin_spans)
Expand Down
10 changes: 5 additions & 5 deletions exporter/zipkin/lib/opentelemetry/exporter/zipkin/transformer.rb
Original file line number Diff line number Diff line change
Expand Up @@ -38,8 +38,8 @@ module Transformer
private_constant(:KIND_MAP, :DEFAULT_SERVICE_NAME, :SERVICE_NAME_ATTRIBUTE_KEY, :ERROR_TAG_KEY, :STATUS_CODE_NAME, :STATUS_ERROR, :STATUS_OK, :ATTRIBUTE_PEER_SERVICE, :ATTRIBUTE_NET_PEER_IP, :ATTRIBUTE_NET_PEER_PORT, :ATTRIBUTE_NET_HOST_IP, :ATTRIBUTE_NET_HOST_PORT)

def to_zipkin_span(span_d, resource)
start_time = (span_d.start_timestamp.to_f * 1_000_000).to_i
duration = (span_d.end_timestamp.to_f * 1_000_000).to_i - start_time
start_time = span_d.start_timestamp / 1_000
duration = span_d.end_timestamp / 1_000 - start_time
tags = {}
service_name = DEFAULT_SERVICE_NAME
resource.attribute_enumerator.select do |key, value|
Expand Down Expand Up @@ -91,7 +91,7 @@ def add_status_tags(span_data, tags)
def add_conditional_tags(zipkin_span, span_data, tags, service_name)
zipkin_span['tags'] = tags unless tags.empty?
zipkin_span['kind'] = KIND_MAP[span_data.kind] unless span_data.kind.nil?
zipkin_span['parentId'] = span_data.parent_span_id.unpack1('H*') unless span_data.parent_span_id.nil?
zipkin_span['parentId'] = span_data.hex_parent_span_id unless span_data.parent_span_id == OpenTelemetry::Trace::INVALID_SPAN_ID
zipkin_span['localEndpoint'] = endpoint_from_tags(tags, (span_data.attributes && span_data.attributes[SERVICE_NAME_ATTRIBUTE_KEY]) || service_name)
# remote endpoint logic https://github.com/open-telemetry/opentelemetry-collector/blob/347cfa9ab21d47240128c58c9bafcc0014bc729d/translator/trace/zipkin/traces_to_zipkinv2.go#L284
zipkin_span['remoteEndpoint'] = endpoint_from_tags(tags, nil)
Expand All @@ -107,12 +107,12 @@ def add_annotations(zipkin_span, span_data)
events = span_data.events.map do |event|
if event.attributes.keys.length.zero?
{
timestamp: (event.timestamp.to_f * 1_000_000).to_s,
timestamp: (event.timestamp / 1_000).to_s,
value: event.name
}
else
{
timestamp: (event.timestamp.to_f * 1_000_000).to_s,
timestamp: (event.timestamp / 1_000).to_s,
value: { event.name => event.attributes.transform_values(&:to_s) }.to_json
}
end
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -146,8 +146,8 @@
end

def create_resource_span_data(name: '', kind: nil, status: nil, parent_span_id: OpenTelemetry::Trace::INVALID_SPAN_ID,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: Time.now,
end_timestamp: Time.now, attributes: nil, links: nil, events: nil, resource: nil,
total_recorded_attributes: 0, total_recorded_events: 0, total_recorded_links: 0, start_timestamp: exportable_timestamp,
end_timestamp: exportable_timestamp, attributes: nil, links: nil, events: nil, resource: nil,
instrumentation_library: OpenTelemetry::SDK::InstrumentationLibrary.new('', 'v0.0.1'),
span_id: OpenTelemetry::Trace.generate_span_id, trace_id: OpenTelemetry::Trace.generate_trace_id,
trace_flags: OpenTelemetry::Trace::TraceFlags::DEFAULT, tracestate: nil)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -35,10 +35,10 @@
attributes = { 'akey' => 'avalue', 'bar' => 'baz' }
events = [
OpenTelemetry::SDK::Trace::Event.new(
name: 'event_with_attribs', attributes: { 'ekey' => 'evalue' }
'event_with_attribs', { 'ekey' => 'evalue' }, exportable_timestamp
),
OpenTelemetry::SDK::Trace::Event.new(
name: 'event_no_attrib', attributes: nil
'event_no_attrib', {}, exportable_timestamp
)
]

Expand All @@ -49,10 +49,10 @@
annotation_one = encoded_span[:annotations].first
annotation_two = encoded_span[:annotations][1]

_(annotation_one[:timestamp]).must_equal((events[0].timestamp.to_f * 1_000_000).to_s)
_(annotation_one[:timestamp]).must_equal((events[0].timestamp / 1_000).to_s)
_(annotation_one[:value]).must_equal({ 'event_with_attribs' => { 'ekey' => 'evalue' } }.to_json)

_(annotation_two[:timestamp]).must_equal((events[1].timestamp.to_f * 1_000_000).to_s)
_(annotation_two[:timestamp]).must_equal((events[1].timestamp / 1_000).to_s)
_(annotation_two[:value]).must_equal('event_no_attrib')

tags = encoded_span['tags']
Expand All @@ -63,7 +63,7 @@
attributes = { 'akey' => ['avalue'], 'bar' => 'baz' }
events = [
OpenTelemetry::SDK::Trace::Event.new(
name: 'event_with_attribs', attributes: { 'ekey' => ['evalue'] }
'event_with_attribs', { 'ekey' => ['evalue'] }, exportable_timestamp
)
]

Expand All @@ -73,7 +73,7 @@

annotation_one = encoded_span[:annotations].first

_(annotation_one[:timestamp]).must_equal((events[0].timestamp.to_f * 1_000_000).to_s)
_(annotation_one[:timestamp]).must_equal((events[0].timestamp / 1000).to_s)
_(annotation_one[:value]).must_equal({ 'event_with_attribs' => { 'ekey' => '["evalue"]' } }.to_json)

tags = encoded_span['tags']
Expand Down
4 changes: 2 additions & 2 deletions exporter/zipkin/test/test_helper.rb
Original file line number Diff line number Diff line change
Expand Up @@ -21,8 +21,8 @@ def create_span_data(status: nil, kind: nil, attributes: nil, events: nil, links
0,
0,
0,
Time.now,
Time.now,
exportable_timestamp,
exportable_timestamp,
attributes,
links,
events,
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -77,9 +77,9 @@ def job_data

_(span.events.size).must_equal 2
_(span.events[0].name).must_equal 'created_at'
_(span.events[0].timestamp).must_be_kind_of Time
_(span.events[0].timestamp).must_be_kind_of Integer
_(span.events[1].name).must_equal 'run_at'
_(span.events[1].timestamp).must_be_kind_of Time
_(span.events[1].timestamp).must_be_kind_of Integer
end

describe 'when queue name is set' do
Expand Down Expand Up @@ -141,11 +141,11 @@ def job_data

_(span.events.size).must_equal 3
_(span.events[0].name).must_equal 'created_at'
_(span.events[0].timestamp).must_be_kind_of Time
_(span.events[0].timestamp).must_be_kind_of Integer
_(span.events[1].name).must_equal 'run_at'
_(span.events[1].timestamp).must_be_kind_of Time
_(span.events[1].timestamp).must_be_kind_of Integer
_(span.events[2].name).must_equal 'locked_at'
_(span.events[2].timestamp).must_be_kind_of Time
_(span.events[2].timestamp).must_be_kind_of Integer
end

describe 'when queue name is set' do
Expand Down Expand Up @@ -184,7 +184,7 @@ def job_data
_(span.attributes['messaging.delayed_job.name']).must_equal 'ErrorPayload'
_(span.events.size).must_equal 4
_(span.events[3].name).must_equal 'exception'
_(span.events[3].timestamp).must_be_kind_of Time
_(span.events[3].timestamp).must_be_kind_of Integer
_(span.events[3].attributes['exception.type']).must_equal 'ArgumentError'
_(span.events[3].attributes['exception.message']).must_equal 'This job failed'
end
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -316,7 +316,7 @@ module MongoTraceTest
refute(span.attributes.key?('db.statement'))
_(span.events.size).must_equal 1
_(span.events[0].name).must_equal 'exception'
_(span.events[0].timestamp).must_be_kind_of Time
_(span.events[0].timestamp).must_be_kind_of Integer
_(span.events[0].attributes['exception.type']).must_equal 'CommandFailed'
_(span.events[0].attributes['exception.message']).must_equal 'ns not found (26)'
end
Expand Down Expand Up @@ -355,7 +355,7 @@ module MongoTraceTest
_(span.attributes['db.operation']).must_equal 'saslStart'
_(span.events.size).must_equal 1
_(span.events[0].name).must_equal 'exception'
_(span.events[0].timestamp).must_be_kind_of Time
_(span.events[0].timestamp).must_be_kind_of Integer
_(span.events[0].attributes['exception.type']).must_equal 'CommandFailed'
_(span.events[0].attributes['exception.message']).must_match(/mechanism.+PLAIN.+\(2\)/)
end
Expand Down
43 changes: 7 additions & 36 deletions sdk/lib/opentelemetry/sdk/trace/event.rb
Original file line number Diff line number Diff line change
Expand Up @@ -7,42 +7,13 @@
module OpenTelemetry
module SDK
module Trace
# A text annotation with a set of attributes and a timestamp.
class Event
EMPTY_ATTRIBUTES = {}.freeze

private_constant :EMPTY_ATTRIBUTES

# Returns the name of this event
#
# @return [String]
attr_reader :name

# Returns the frozen attributes for this event
#
# @return [Hash{String => String, Numeric, Boolean, Array<String, Numeric, Boolean>}]
attr_reader :attributes

# Returns the timestamp for this event
#
# @return [Time]
attr_reader :timestamp

# Returns a new immutable {Event}.
#
# @param [String] name The name of this event
# @param [optional Hash{String => String, Numeric, Boolean, Array<String, Numeric, Boolean>}]
# attributes A hash of attributes for this event. Attributes will be
# frozen during Event initialization.
# @param [optional Time] timestamp The timestamp for this event.
# Defaults to Time.now.
# @return [Event]
def initialize(name:, attributes: nil, timestamp: nil)
@name = name
@attributes = attributes.freeze || EMPTY_ATTRIBUTES
@timestamp = timestamp || Time.now
end
end
# A text annotation with a set of attributes and a timestamp for export.
#
# Field types are as follows:
# name: String
# attributes: frozen Hash{String => String, Numeric, Boolean, Array<String, Numeric, Boolean>}
# timestamp: Integer nanoseconds since Epoch
Event = Struct.new(:name, :attributes, :timestamp)
end
end
end
Original file line number Diff line number Diff line change
Expand Up @@ -101,7 +101,7 @@ def on_finish(span) # rubocop:disable Metrics/AbcSize
# @return [Integer] SUCCESS if no error occurred, FAILURE if a
# non-specific failure occurred, TIMEOUT if a timeout occurred.
def force_flush(timeout: nil) # rubocop:disable Metrics/AbcSize, Metrics/CyclomaticComplexity, Metrics/PerceivedComplexity, Metrics/MethodLength
start_time = Time.now
start_time = OpenTelemetry::Common::Utilities.timeout_timestamp
snapshot = lock do
reset_on_fork if @keep_running
spans.shift(spans.size)
Expand Down Expand Up @@ -137,7 +137,7 @@ def force_flush(timeout: nil) # rubocop:disable Metrics/AbcSize, Metrics/Cycloma
# @return [Integer] SUCCESS if no error occurred, FAILURE if a
# non-specific failure occurred, TIMEOUT if a timeout occurred.
def shutdown(timeout: nil)
start_time = Time.now
start_time = OpenTelemetry::Common::Utilities.timeout_timestamp
thread = lock do
@keep_running = false
@condition.signal
Expand Down
Loading

0 comments on commit 50ce54b

Please sign in to comment.