Shopify / statsd-instrument

A StatsD client for Ruby apps. Provides metaprogramming methods to inject StatsD instrumentation into your code.
http://shopify.github.io/statsd-instrument
MIT License
574 stars 97 forks source link

`normalize_tags` is quite expensive in aggregate. #357

Closed ptolts closed 1 year ago

ptolts commented 1 year ago

I've been profiling application code and I've noticed that normalize_tags is quite expensive when statsd is used at scale. The profile below represents a significant overhead for the profile in question.

statsd-instrument 3.5.12

image
   def normalize_tags(tags)
        return [] unless tags

        tags = tags.map { |k, v| "#{k}:#{v}" } if tags.is_a?(Hash)

        # Fast path when no string replacement is needed
        return tags unless tags.any? { |tag| /[|,]/.match?(tag) }

        tags.map { |tag| tag.tr("|,", "") }
      end

https://github.com/Shopify/statsd-instrument/blob/e39f8ec3a3c18f6b7625b5686e94abea1ceb1301/lib/statsd/instrument/datagram_builder.rb#L70-L79

casperisfine commented 1 year ago

Yeah, it's in big part caused by how liberal it is in the arguments it accepts. If it was stricter, we could optimize a bit better.

I'll still see if I can pull something

casperisfine commented 1 year ago

So by pulling about all tricks in the book, inlining agressively, avoiding allocations, and more importantly, not normalizing the data, I get ~1.4-1.5x speedup:

$ ruby /tmp/bench-statsd-tags.rb 
3.2.2
===== small =====
Warming up --------------------------------------
            baseline    58.860k i/100ms
                 opt    79.446k i/100ms
Calculating -------------------------------------
            baseline    586.238k (± 3.9%) i/s -      2.943M in   5.028426s
                 opt    819.330k (± 8.2%) i/s -      4.131M in   5.095622s

Comparison:
            baseline:   586238.4 i/s
                 opt:   819329.9 i/s - 1.40x  faster

$ ruby /tmp/bench-statsd-tags.rb 
3.2.2
===== small =====
Warming up --------------------------------------
            baseline    60.072k i/100ms
                 opt    56.201k i/100ms
Calculating -------------------------------------
            baseline    582.379k (± 9.8%) i/s -      2.883M in   5.075574s
                 opt    806.902k (±13.4%) i/s -      3.822M in   5.002069s

Comparison:
            baseline:   582378.8 i/s
                 opt:   806902.2 i/s - 1.39x  faster

$ ruby /tmp/bench-statsd-tags.rb 
3.2.2
===== small =====
Warming up --------------------------------------
            baseline    31.277k i/100ms
                 opt    84.932k i/100ms
Calculating -------------------------------------
            baseline    591.086k (± 2.3%) i/s -      2.971M in   5.029619s
                 opt    839.842k (± 1.7%) i/s -      4.247M in   5.057857s

Comparison:
            baseline:   591085.7 i/s
                 opt:   839842.2 i/s - 1.42x  faster

$ ruby --yjit /tmp/bench-statsd-tags.rb 
3.2.2
===== small =====
Warming up --------------------------------------
            baseline    74.684k i/100ms
                 opt   111.307k i/100ms
Calculating -------------------------------------
            baseline    775.749k (± 2.1%) i/s -      3.884M in   5.008461s
                 opt      1.165M (± 1.7%) i/s -      5.899M in   5.065578s

Comparison:
            baseline:   775748.8 i/s
                 opt:  1164944.7 i/s - 1.50x  faster

$ ruby --yjit /tmp/bench-statsd-tags.rb 
3.2.2
===== small =====
Warming up --------------------------------------
            baseline    74.336k i/100ms
                 opt   111.825k i/100ms
Calculating -------------------------------------
            baseline    775.090k (± 3.5%) i/s -      3.940M in   5.089749s
                 opt      1.159M (± 1.8%) i/s -      5.815M in   5.017798s

Comparison:
            baseline:   775090.2 i/s
                 opt:  1159224.1 i/s - 1.50x  faster
# frozen_string_literal: true

require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'
  gem 'benchmark-ips'
end

class DatagramBuilder
  def initialize(prefix: nil, default_tags: nil)
    @prefix = prefix.nil? ? "" : "#{normalize_name(prefix)}."
    @default_tags = normalize_tags(default_tags)
  end

  def d(name, value, sample_rate, tags)
    generate_generic_datagram(name, value, "d", sample_rate, tags)
  end

  protected

  attr_reader :prefix, :default_tags

  # Utility function to convert tags to the canonical form.
  #
  # - Tags specified as key value pairs will be converted into an array
  # - Tags are normalized to remove unsupported characters
  #
  # @param tags [Array<String>, Hash<String, String>, nil] Tags specified in any form.
  # @return [Array<String>, nil] the list of tags in canonical form.
  def normalize_tags(tags)
    return [] unless tags

    tags = tags.map { |k, v| "#{k}:#{v}" } if tags.is_a?(Hash)

    # Fast path when no string replacement is needed
    return tags unless tags.any? { |tag| /[|,]/.match?(tag) }

    tags.map { |tag| tag.tr("|,", "") }
  end

  # Utility function to remove invalid characters from a StatsD metric name
  def normalize_name(name)
    # Fast path when no normalization is needed to avoid copying the string
    return name unless /[:|@]/.match?(name)

    name.tr(":|@", "_")
  end

  def generate_generic_datagram(name, value, type, sample_rate, tags)
    tags = normalize_tags(tags) + default_tags
    datagram = +"#{@prefix}#{normalize_name(name)}:#{value}|#{type}"
    datagram << "|@#{sample_rate}" if sample_rate && sample_rate < 1
    datagram << "|##{tags.join(",")}" unless tags.empty?
    datagram
  end
end

class OptBuilder < DatagramBuilder
  def initialize(prefix: nil, default_tags: nil)
    @prefix = prefix.nil? ? "" : "#{normalize_name(prefix)}."
    @default_tags = default_tags.nil? || default_tags.empty? ? nil : normalize_tags(default_tags)
  end

  def normalize_tags(tags)
    if tags
      tags.map { |k, v| "#{k}:#{v}" }.join(",")
    else
      ""
    end
  end

  def generate_generic_datagram(name, value, type, sample_rate, tags)
    datagram = "".b << @prefix << (/[:|@]/.match?(name) ? name.tr(":|@", "_") : name) << ":" << value.to_s << "|" << type
    datagram << "|@" << sample_rate.to_s if sample_rate && sample_rate < 1

    unless @default_tags.nil?
      datagram << "|#" << @default_tags
    end

    unless tags.nil?
      if @default_tags.nil?
        datagram << "|#"
      end

      first = true
      tags.each do |key, value|
        if first
          first = false
        else
          datagram << ","
        end
        datagram << key.to_s << ":" << value.to_s
      end
      # datagram << normalize_tags(tags)
    end

    datagram
  end
end

builder = DatagramBuilder.new
opt_builder = OptBuilder.new

tags = { foo: "bar", egg: "spam" }

d1 = builder.d("AppName.response_time", 12.34, 1, tags)
d2 = opt_builder.d("AppName.response_time", 12.34, 1, tags)
p d2.bytesize

raise "Oops" unless d1 == d2

puts RUBY_VERSION
puts "===== small ====="
Benchmark.ips do |x|
  x.report("baseline") do
    builder.d("AppName.response_time", 12.34, 1, tags)
  end

  x.report("opt") do
    opt_builder.d("AppName.response_time", 12.34, 1, tags)
  end

  x.compare!(order: :baseline)
end

Not saying we should do all that, but it gives an idea of how far we could go.

wvanbergen commented 1 year ago

It's been ages, but I think there is a way to call the statsd instrumentation functions that bypasses most of the normalization and cleanup code, specifically for hot code paths. I remember porting a bunch of the hot paths in the monolith.

casperisfine commented 1 year ago

O, #358 made the datagram builder ~1.4x faster (I kept the normalization).

Overall benchmark/send-metrics-to-dev-null-log is 1.15x faster, but it uses fairly few tags so might be a bit more in real world.

I don't think there's much more we can do, so if after this change it's still a significant part of your request time, I'd suggest looking at how many metrics you emit and consider if they're all really useful.