Que jobs running concurrently have interference on Rails 5.

[bramski]

Hello,

We're having a consistently repeatable problem over here of what we think is a fundamental problem of the MVCC advisory lock model in use here.

I see this code, and it doesn't seem to be effective:
https://github.com/chanks/que/blob/master/lib/que/job.rb#L88

Screenshot of our logs:

Our Job Runner Looks like:

require 'que'

module ActiveJob
  module QueueAdapters
    class ImhrJobRunner < ::Que::Job
      # Places the que job in job_data["que_ref"]
      # which can be picked up by ApplicationJob
      def run(job_data)
        @job_data = job_data

        if que_job_done? # we only need to check cause Que picks up destroyed jobs.
          log_rerun_issue_info
        else
          job_data["que_ref"] = self
          ApplicationJob.execute job_data
        end

        mark_que_job_as_done # if you reach this point it's done
      end

      public :destroy

      private

      attr_reader :job_data

      def log_rerun_issue_info
        Rails.logger.warn "#{self.class.name}: Que tried to rerun #{job_data["job_class"]}: " \
                          "#{job_data["job_id"]}"
      end

      def que_job_done?
        Rails.cache.exist?(que_job_cache_key)
      end

      def mark_que_job_as_done
        Rails.cache.write(que_job_cache_key, true, expires_in: 10.seconds)
      end

      def que_job_cache_key
        ["que-job-done", job_data["job_id"]].join("-")
      end
    end
  end
end

We've added Rails cache which uses redis to ensure that the jobs aren't being run twice.

[bramski]

Does the WARNING: you don't own a lock type of ExclusiveLock have something to do with this?

[chanks]

That warning message would come up if you try to release an advisory lock that hasn't been taken by that connection (it might also come up in other cases). Are you using pgbouncer, or some other connection pool outside the app? That may cause that message. Or, are you doing anything unusual with your PG connections?

Are you sure the job is being destroyed after it is run? Que tries to destroy jobs on its own that you haven't explicitly called destroy on, but it uses a @destroyed instance variable in the job instance itself to determine whether that is necessary, and your logic may be writing to that variable? Or possibly you're calling destroy in a savepoint that's getting rolled back while the main transaction continues to completion? The fact that you've marked destroy as public is a little suspicious to me, but I don't know what your actual job logic looks like.

[bramski]

It's just Que & AR. No pgbouncer.
Destroy was made public so that we can put it inside the transaction explicitly and expose it to the AJ job.
The transaction isn't cancelling or getting rolled back. In fact in the log you're seeing there is no transaction on the job which is repeating. Adding a transaction to that job made it less consistently repeatable, but still repeatable.

[bramski]

The job is definitely destroyed. We added an AR model to check it's existence when being run and it's typically not there. About 80%, but it's still possible that the AR connection thinks the job is there. I'm guessing due to the same MVCC problem that the code states. Redis-style locking manages to be consistent here.

[joevandyk]

Is this running in Rails production mode?

[bramski]

Seeing it in staging and production.

[bramski]

We've tuned the que worker to be more rapidly responsive. We were seeing this rather intermittently and then tuned the worker wake interval to 0.01 and started seeing this much more consistently.

[chanks]

That's not a ridiculous wake interval. I still suspect that there's something unusual about your setup, or perhaps your Postgres configuration? Have you changed the default transaction isolation, or are you somehow running the workers themselves inside of a transaction?

I doubt that there's anything fundamentally unexpected about advisory locks and how they interact with MVCC, or it would have come up sometime in the last three years. Of course, if you had a self-contained reproduction that demonstrated the issue, that would be helpful.

[chanks]

Also, I don't know what's causing those "you don't own a lock type of ExclusiveLock" warnings, those aren't a normal thing and are a signifier that something is wrong.

[bramski]

Postgres is vanilla heroku.
Version:
PostgreSQL 9.5.2 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit

We haven't done anything to the transaction isolation.
Procfile:

web: bundle exec puma -C config/puma.rb
worker: bundle exec que --worker-count $WORKER_QUE_WORKERS --wake-interval $WORKER_QUE_WAKE_INTERVAL ./config/environment.rb

[bramski]

Postgres Settings:
postgres_settings.txt

it's actually a csv. so rename and open. GH doesn't seem to like csv files.

[bramski]

Looks like read_committed is the default for the heroku PG instances.

[joevandyk]

Is there anything in your code/job that could be starting new database connections? Forking processes for example? Or stopping processes?

That warning indicates that the advisory lock is being dropped and so it would make sense that Que would re-run the job.

[bramski]

You are looking at all the code pre-AJ @joevandyk . Nothing fancy after that. Just business logic.

[bramski]

We haven't changed the Que.mode, but we are running a separate que process.