PG::UnableToSend: another command is already in progress

Issue #194 resolved
Hendrik Kleinwächter
created an issue

Hi there,

awesome work, thanks a bunch for the gem.

We are receiving the following error quite frequently. We just upgraded from Rails 3 to Rails 4. Also upgraded the postgres gem.

Error Message:
PG::UnableToSend: another command is already in progress
: SELECT  "adwords_caches".* FROM "adwords_caches"  WHERE "adwords_caches"."adwords_campaign_id" = $1 AND "adwords_caches"."day" = '2014-11-22'  ORDER BY "adwords_caches"."id" ASC LIMIT 1

Stacktrace:
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:832:in `send_query_prepared'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:832:in `block in exec_cache'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/abstract_adapter.rb:373:in `block in log'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activesupport-4.1.7/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/abstract_adapter.rb:367:in `log'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:831:in `exec_cache'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/postgresql/database_statements.rb:138:in `exec_query'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/postgresql_adapter.rb:954:in `select'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/abstract/database_statements.rb:24:in `select_all'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/connection_adapters/abstract/query_cache.rb:70:in `select_all'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/querying.rb:39:in `find_by_sql'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation.rb:611:in `exec_queries'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/association_relation.rb:19:in `exec_queries'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation.rb:493:in `load'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation.rb:238:in `to_a'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation/finder_methods.rb:474:in `find_nth_with_limit'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation/finder_methods.rb:468:in `find_nth'
/home/deployer/.rbenv/versions/2.1.5/lib/ruby/gems/2.1.0/gems/activerecord-4.1.7/lib/active_record/relation/finder_methods.rb:132:in `first'
/home/deployer/apps/robot/app/models/adwords_campaign.rb:506:in `adwords_day_data'
/home/deployer/apps/robot/app/workers/recurring/fetch_adwords_data.rb:35:in `perform_for_campaign'
/home/deployer/apps/robot/app/workers/recurring/fetch_adwords_data.rb:21:in `block (3 levels) in perform'

This is the actual code that is called:

  def adwords_day_data(day, attributes_to_update: [])
    date = day.to_date

    # Error happens on this line.
    existing_cache = adwords_cache.where(:day => date).first

    # If we found a cache and shouldn't update return the cache
    return existing_cache if existing_cache && attributes_to_update.blank?

    # Get the data from adwords
    new_cache = get_adwords_data_for_date(date)

    # Update the existing cache with data from a new cache
    if attributes_to_update.present? && existing_cache.present?
      existing_cache = assign_new_values_to_cache(cache_with_new_values: new_cache, base_cache: existing_cache, attributes: attributes_to_update)
      existing_cache.save
      existing_cache
    # Else persist the new cache
    elsif date <= AdwordsCache::DELAY_DAYS.days.ago.to_date
      new_cache.save
      new_cache
    # Return the cache without saving
    else
      new_cache
    end
  end

Any ideas what I could be doing wrong?

This happens in a Sidekiq process that has a couple of threads (30). Could this relate to the issue?

Thanks!

Comments (5)

  1. Lars Kanis

    Like the error message says, there is an unfinished command in process, while the call to adwords_cache.first . It could be a threading issue, but usually rails connection pooling ensures that each thread uses it's own connection. However this is not true, when using connection objects directly.

    You should try to find out, which command is still in process. You can use logging or wireshark for it.

  2. Hendrik Kleinwächter reporter

    Thanks Lars. How would I go about the logging in this case? Is there a way to check for other postgres commands currently running?

    We have many processes with 1 thread each. Each of them has a connection pool size of 5.

  3. Log in to comment