Record stats for serialization time

[plantfansam]

Serialization takes place during export and is a resource-intensive process; users may want to see how long it takes.

Remnants of earlier approach

I had to prove to myself that the value returned from a block passed to a block-handling function will be returned from the block-handling function even when there's an ensure in that function (I was worried that something from the ensure block would be returned). For documentation, I'll reproduce that experiment here:

Given the Ruby

def mymethod
  "return from mymethod"
end

def wrap_mymethod
  begin
    yield
  ensure
    puts "Ensure ran within wrap_mymethod"
  end
end


ret = wrap_mymethod { mymethod }

puts "Return value from `wrap_mymethod`: #{ret}"

Yields output:

ruby yield.rb
Ensure ran within wrap_mymethod
Return value from `wrap_mymethod`: return from mymethod

[plantfansam]

Instead of mocking the metrics reporter, we could move InMemoryMetricsReporter from https://github.com/open-telemetry/opentelemetry-ruby/blob/2bcb4643b144300b0e18cba6ae61e93eb75bc5b0/exporter/zipkin/test/test_helper.rb#L43-L42 to opentelemetry-test-helpers if reviewers would like.

[fbogsany]

I think we should inline measure_encode_duration into the encode method. We didn't do that with measure_request_duration because the block it wraps is a stdlib method (@http.request(request)).

[plantfansam]

Sure thing

[plantfansam]

just an indentation change

[fbogsany]

Sorry, I was unclear in my earlier comment. I don't think we need measure_encode_duration. We just need to ... measure the duration of the encode method. I.e.

        def encode(span_data) # rubocop:disable Metrics/MethodLength, Metrics/CyclomaticComplexity
          start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
          Opentelemetry::Proto::Collector::Trace::V1::ExportTraceServiceRequest.encode(
            Opentelemetry::Proto::Collector::Trace::V1::ExportTraceServiceRequest.new(
              resource_spans: span_data
                .group_by(&:resource)
                .map do |resource, span_datas|
                  Opentelemetry::Proto::Trace::V1::ResourceSpans.new(
                    resource: Opentelemetry::Proto::Resource::V1::Resource.new(
                      attributes: resource.attribute_enumerator.map { |key, value| as_otlp_key_value(key, value) }
                    ),
                    scope_spans: span_datas
                      .group_by(&:instrumentation_scope)
                      .map do |il, sds|
                        Opentelemetry::Proto::Trace::V1::ScopeSpans.new(
                          scope: Opentelemetry::Proto::Common::V1::InstrumentationScope.new(
                            name: il.name,
                            version: il.version
                          ),
                          spans: sds.map { |sd| as_otlp_span(sd) }
                        )
                      end
                  )
                end
              )
            )
        rescue StandardError => e
          OpenTelemetry.handle_error(exception: e, message: 'unexpected error in OTLP::Exporter#encode')
          nil
        ensure
          stop = Process.clock_gettime(Process::CLOCK_MONOTONIC)
          duration_ms = 1000.0 * (stop - start)
          @metrics_reporter.record_value('otel.otlp_exporter.encode_duration',
                                         value: duration_ms)
        end

[plantfansam]

Yeah, this makes more sense; I was on autopilot. Will make change.

[arielvalentin]

How would y'all feel about adding a helper that accepts a block:

@metrics_reporter.record_duration(name, labels: labels) do
   # your code we want to measure goes here
end

[fbogsany]

If we do this one more time, it's worth a refactor. I am not super keen on the block-based approach if all our callsites are full methods. I think I'd prefer:

def foo
  probe = start_probe('otel.otlp_exporter.foo')
  ...
ensure
  probe.finish
end

over:

def foo
  @metrics_reporter.record_duration('otel.otlp_exporter.foo') do
    ...
  end
end

simply because it avoids deeper indentation as we add instrumentation to existing methods. The latter is better for measurements of small chunks of code within a larger method.