Module: Sixty::Tracer

Defined in:
lib/sixty/tracer.rb

Overview

Span lifecycle and context propagation.

The important property, and it is the same one the Node agent has: EVERY call is measured, but only a few are transmitted as traces. Spans are cheap objects that feed a local aggregator; full span trees are serialized only for sampled traces, errors and latency outliers. That is what keeps both agent overhead and ingest cost proportional to cardinality rather than to traffic.

Attribution rules, which are the whole reason this file exists:

self time — duration minus the sum of direct children. "Did MY code get
          slower, or did something I called get slower?"
db calls  — every descendant db span, credited to every ancestor. A method
          going from 3 to 47 queries is an N+1 being born, and it has to
          be visible on the method, not only on the query.
rows      — the same transitive credit. This is the 30 -> 30,000 signal.

── How "the current span" is tracked ─────────────────────────────────────

Thread.current[] is fiber-local storage, which is the closest thing Ruby has to Node's AsyncLocalStorage. Under Puma, Unicorn and Sidekiq — a thread or a process per unit of work — it is exactly right. Under a fiber scheduler (Falcon, async gem) each fiber starts with an empty context instead of inheriting its parent's, so a query issued inside a spawned fiber is recorded with correct timings but no parent. The counts stay right; the edge is lost. That trade is stated here rather than discovered later, and it is the same shape of limitation core's synchronous context has in browsers.

Defined Under Namespace

Classes: Span

Constant Summary collapse

KIND_HTTP = 
'http'
KIND_FUNCTION = 
'function'
KIND_DB = 
'db'
MAX_SPANS_PER_TRACE =

A single pathological request — the N+1 this product exists to catch — can emit tens of thousands of spans. Aggregates must still count every one of them, but the retained tree is capped so one bad request cannot exhaust memory.

500
KEY = 
:sixty_span

Class Attribute Summary collapse

Class Method Summary collapse

Class Attribute Details

.sink ⇒ Object

Returns the value of attribute sink.



75
76
77
 
# File 'lib/sixty/tracer.rb', line 75

def sink
  @sink
end

Class Method Details

.current ⇒ Object 



77
78
79
 
# File 'lib/sixty/tracer.rb', line 77

def current
  Thread.current[KEY]
end

.current=(span) ⇒ Object 



81
82
83
 
# File 'lib/sixty/tracer.rb', line 81

def current=(span)
  Thread.current[KEY] = span
end

.emit(span) ⇒ Object

Handing a span to the sink can never fail the code being measured.

This runs inside somebody's request path — between their query returning and their controller resuming — so a raise here does not lose a measurement, it fails their request. Sixty.on_span_end rescues and warns, which is where an agent bug should be noticed; this is the floor underneath that, for a sink installed by anything else. Losing one span is recoverable and invisible. Breaking the host application is neither.



199
200
201
202
203
204
 
# File 'lib/sixty/tracer.rb', line 199

def emit(span)
  handler = @sink
  handler&.call(span)
rescue StandardError
  nil
end

.end_span(span, error = nil, duration: nil) ⇒ Object 



116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
 
# File 'lib/sixty/tracer.rb', line 116

def end_span(span, error = nil, duration: nil)
  return span if span.duration # already ended; guard double-finish

  span.duration = duration || (monotonic_ms - span.start)
  if error
    span.error = {
      # Class name and message only. A backtrace can contain file paths
      # and interpolated values; we take the message but never the args.
      type: error.class.name.to_s[0, 200],
      message: error.message.to_s[0, 500]
    }
  end

  parent = span.parent
  if parent
    parent.child_duration += span.duration
    parent.children << span unless span.root.truncated
  end

  # Credit db work to every ancestor, not only the immediate parent.
  if span.kind == KIND_DB
    rows = span.attrs[:rows].is_a?(Numeric) ? span.attrs[:rows] : 0
    ancestor = span.parent
    while ancestor
      ancestor.db_calls += 1
      ancestor.db_rows += rows
      ancestor = ancestor.parent
    end
  end

  span
end

.in_span(span) ⇒ Object

Run a block with span as the active context, ending and emitting it however the block leaves — returned value, raised error, or throw.



155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
 
# File 'lib/sixty/tracer.rb', line 155

def in_span(span)
  previous = current
  self.current = span
  begin
    result = yield
  rescue Exception => e # rubocop:disable Lint/RescueException
    # Exception, not StandardError: a Timeout::Error or an Interrupt still
    # ended this span, and losing the measurement is the smaller problem
    # than leaving the context pointing at a span that never closed.
    self.current = previous
    end_span(span, e)
    emit(span)
    raise
  end
  self.current = previous
  end_span(span)
  emit(span)
  result
end

.monotonic_ms ⇒ Object 



206
207
208
 
# File 'lib/sixty/tracer.rb', line 206

def monotonic_ms
  Process.clock_gettime(Process::CLOCK_MONOTONIC) * 1000.0
end

.record(kind:, name:, duration_ms:, attrs: {}, start_wall: nil, error: nil) ⇒ Object

Record a span that has already happened.

ActiveSupport::Notifications hands an event to its subscriber after the work finished, with its own start and finish times — so there is nothing to run a block around. The span is assembled with those times and parented to whatever is current, which is correct because the subscriber runs synchronously on the same thread as the query it describes.



183
184
185
186
187
188
189
 
# File 'lib/sixty/tracer.rb', line 183

def record(kind:, name:, duration_ms:, attrs: {}, start_wall: nil, error: nil)
  span = start_span(kind: kind, name: name, attrs: attrs)
  span.start_wall = start_wall if start_wall
  end_span(span, error, duration: duration_ms)
  emit(span)
  span
end

.self_time(span) ⇒ Object 



149
150
151
 
# File 'lib/sixty/tracer.rb', line 149

def self_time(span)
  [0.0, span.duration.to_f - span.child_duration.to_f].max
end

.start_span(kind:, name:, attrs: nil) ⇒ Object 



85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
 
# File 'lib/sixty/tracer.rb', line 85

def start_span(kind:, name:, attrs: nil)
  parent = current
  span = Span.new(kind, name, attrs || {}, parent)
  span.id = next_id
  span.start = monotonic_ms

  if parent
    span.trace_id = parent.trace_id
    span.parent_id = parent.id
    span.depth = parent.depth + 1
    span.root = parent.root
  else
    # Only a root pays for entropy and for a wall clock. Child spans are
    # never looked up by time or id outside the tree they belong to, and
    # this runs on every instrumented call in the application.
    span.trace_id = SecureRandom.hex(16)
    span.parent_id = nil
    span.depth = 0
    span.root = span
    span.start_wall = (Time.now.to_f * 1000).round
  end

  # Children are always collected: whether a trace is worth keeping is
  # only knowable once it finishes (did it raise? was it slow?), and a
  # tree cannot be rebuilt retroactively.
  root = span.root
  root.span_count += 1
  root.truncated = true if root.span_count > MAX_SPANS_PER_TRACE
  span
end