incredibly high mysql latency

development.log

Connecting to database specified by database.yml                                                                                                                                            [1286/9658]
Starting the New Relic Agent.
NewRelic Agent Developer Mode enabled.
To view performance information, go to http://localhost:3000/newrelic
Installed New Relic Browser Monitoring middleware
   (0.3ms)  BEGIN
  ProductType Load (35.7ms)  SELECT `product_types`.* FROM `product_types` WHERE `product_types`.`name` = 'Music' LIMIT 1
  Category Load (0.6ms)  SELECT `categories`.* FROM `categories` WHERE `categories`.`name` = 'Music' LIMIT 1
  Descriptor Load (0.3ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Discogs ID' ORDER BY name LIMIT 1
  Descriptor Load (0.4ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Artists' ORDER BY name LIMIT 1
  Descriptor Load (0.9ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Labels' ORDER BY name LIMIT 1
  Descriptor Load (0.8ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Format' ORDER BY name LIMIT 1
  Descriptor Load (0.7ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Genres' ORDER BY name LIMIT 1
  Descriptor Load (0.6ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Styles' ORDER BY name LIMIT 1
  Descriptor Load (0.6ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Country' ORDER BY name LIMIT 1
  Descriptor Load (0.9ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Released' ORDER BY name LIMIT 1
  Descriptor Load (1.1ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`product_type_id` = 1 AND `descriptors`.`name` = 'Notes' ORDER BY name LIMIT 1
   (0.3ms)  COMMIT

########### all good up here

Starting parser
Waiting on broker
  ImportIdentifier Load (320.1ms)  SELECT `import_identifiers`.* FROM `import_identifiers` WHERE `import_identifiers`.`source` = 'discogs' AND `import_identifiers`.`value` = '1' GROUP BY product_id
  Product Load (269.6ms)  SELECT `products`.* FROM `products` WHERE `products`.`id` IN (1)
  ProductDescriptor Load (522.8ms)  SELECT `product_descriptors`.* FROM `product_descriptors` WHERE `product_descriptors`.`product_id` IN (1)
  Descriptor Load (580.4ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`id` IN (2, 3, 4, 5, 6, 7, 8, 9)

######### DEAR GOD, there's only 9 descriptors in the table

  ImportIdentifier Load (23.7ms)  SELECT `import_identifiers`.* FROM `import_identifiers` WHERE `import_identifiers`.`source` = 'discogs' AND `import_identifiers`.`value` = '2' GROUP BY product_id
  Product Load (620.2ms)  SELECT `products`.* FROM `products` WHERE `products`.`id` IN (2)
  ProductDescriptor Load (16.5ms)  SELECT `product_descriptors`.* FROM `product_descriptors` WHERE `product_descriptors`.`product_id` IN (2)
  Descriptor Load (328.4ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`id` IN (2, 3, 4, 5, 6, 7, 8, 9)
  Category Load (337.8ms)  SELECT `categories`.* FROM `categories` WHERE `categories`.`ancestry` = '3'
  ImportIdentifier Load (13.8ms)  SELECT `import_identifiers`.* FROM `import_identifiers` WHERE `import_identifiers`.`source` = 'discogs' AND `import_identifiers`.`value` = '3' GROUP BY product_id
  Product Load (122.1ms)  SELECT `products`.* FROM `products` WHERE `products`.`id` IN (3)
  ProductDescriptor Load (322.6ms)  SELECT `product_descriptors`.* FROM `product_descriptors` WHERE `product_descriptors`.`product_id` IN (3)
  Descriptor Load (13.5ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`id` IN (2, 3, 4, 5, 6, 7, 8, 9)
  ImportIdentifier Load (250.8ms)  SELECT `import_identifiers`.* FROM `import_identifiers` WHERE `import_identifiers`.`source` = 'discogs' AND `import_identifiers`.`value` = '4' GROUP BY product_id
  Product Load (371.8ms)  SELECT `products`.* FROM `products` WHERE `products`.`id` IN (4)
  ProductDescriptor Load (194.7ms)  SELECT `product_descriptors`.* FROM `product_descriptors` WHERE `product_descriptors`.`product_id` IN (4)
  Descriptor Load (592.8ms)  SELECT `descriptors`.* FROM `descriptors` WHERE `descriptors`.`id` IN (2, 3, 4, 5, 6, 7, 8, 9)
  ProductType Load (19.3ms)  SELECT `product_types`.* FROM `product_types` WHERE `product_types`.`id` = 1 LIMIT 1
   (481.6ms)  BEGIN

importer.rb

module DiscogsImport
  module Benchy
    def benchmark(label)
      time = Time.now.to_f
      res = yield
      puts "#{label} #{"%0.2f" % (Time.now.to_f - time)}"
      res
    end
  end

  class Importer
    class ProductGenerator
      include Benchy

      attr_reader :category_resolver, :release

      def initialize(category_resolver, release)
        @category_resolver = category_resolver
        @release = release
      end

      def generate_products
        formats.map do |format|
          find_or_initialize_product(format)
        end
      end

    private
      def formats
        release.formats.empty? ? [nil] : release.formats
      end

      def find_or_initialize_product(format)
        products = nil
        time = Time.now.to_f
        benchmark("Product by discogs id") do
          products = Product.by_discogs_id(discogs_id)
        end
        product = products.detect {|p| p.descriptor_hash['Format'] == format } ||
          category.products.build

        product.name         = generate_name(format)
        product.product_type = category.product_type
        product
      rescue ActiveRecord::ConnectionTimeoutError
        retry
      end

      def generate_name(format)
        name = release.title
        name << " (#{format})" if format
        name
      end

      def category
        @category ||= category_resolver.resolve_category(release)
      end
    end

    include Celluloid
    include Benchy

    attr_reader :category_resolver

    def initialize(category_resolver)
      @category_resolver = category_resolver
    end

    def save(release)
      return unless release_okay?(release)

      products = ProductGenerator.new(category_resolver,
                                      release).generate_products

      products.each do |product|
        begin
          benchmark("product ident save") do
            transaction do
              product.save! #TODO: error gathering
              identifier = configure_import_identifier(release, product)
              identifier.save!
            end
          end
        rescue ActiveRecord::ConnectionTimeoutError
          retry
        end
      end
    end

  private

    def configure_import_identifier(release, product)
      ImportIdentifier.discogs_id_for(release.discogs_id, product)
    end

    def transaction(&block)
      Product.transaction(&block)
    end

    def release_okay?(release)
      release.accepted?
    end
  end
end

processor.rb

module DiscogsImport
  class Processor
    include Celluloid

    attr_reader :importer_supervisor

    def initialize(category_resolver)
      # No pool. Prone to database timeouts
      @importer_supervisor = DiscogsImport::Importer.supervise(category_resolver)
    end

    # gets called a bunch with each parsed node
    def process(release)
      importer.save(release) 
    end

  private
    def importer
      importer_supervisor.actors.first
    rescue Celluloid::DeadActorError # actor not restarted yet
      retry
    end
  end
end