SELECT FOR UPDATE doesn't block on Rails 3.2.11 with PostgreSQL 9.1

Question

I am trying to use pessimistic lock to avoid race condition. I was expecting the after one thread acquired a row via SELECT FOR UPDATE, another thread looking for the same row will be blocked until the lock is released. However, upon testing, it seems that the lock doesn't hold and the second thread can just acquire the row and update to it, even when the first thread haven't saved (updated) that row yet.

Here is the relevant codes:

Database Schema

class CreateMytables < ActiveRecord::Migration
  def change
    create_table :mytables do |t|
        t.integer  :myID
        t.integer  :attribute1
        t.timestamps
    end

    add_index :mytables, :myID, :unique => true

  end
end

mytables_controller.rb

class MytablessController < ApplicationController

    require 'timeout'

    def create
        myID = Integer(params[:myID])
        begin
            mytable = nil
            Timeout.timeout(25) do 
                p "waiting for lock"              
                mytable = Mytables.find(:first, :conditions => ['"myID" = ?', myID], :lock => true ) #'FOR UPDATE NOWAIT') #true) 
                #mytable.lock!
                p "acquired lock"                 
            end
            if mytable.nil?
                mytable = Mytables.new
                mytable.myID =  myID
            else
                if mytable.attribute1 > Integer(params[:attribute1])
                    respond_to do |format|
                        format.json{
                            render :json => "{\"Error\": \"Update failed, a higher attribute1 value already exist!\", 
\"Error Code\": \"C\"
}"
                            }
                    end
                    return
                end
            end
            mytable.attribute1 =  Integer(params[:attribute1])           
            sleep 15  #1 
            p "woke up from sleep"
            mytable.save! 
            p "done saving"             
            respond_to do |format|
                format.json{
                          render :json => "{\"Success\": \"Update successful!\",
\"Error Code\": \"A\"
}"
                            }
            end
        rescue ActiveRecord::RecordNotUnique #=> e     
            respond_to do |format|
                format.json{
                            render :json => "{\"Error\": \"Update Contention, please retry in a moment!\",
\"Error Code\": \"B\"
}"
                            }
            end
        rescue Timeout::Error
            p "Time out error!!!"
            respond_to do |format|
                format.json{
                            render :json => "{\"Error\": \"Update Contention, please retry in a moment!\",
\"Error Code\": \"B\"
}"
                            }
            end
        end   
    end
end

I have tested it in two settings, one is running the app with unicorn with worker_processes 4 on Heroku, the other is running locally on my machine with PostgreSQL 9.1 set up, running two single thread instance of the app, one is rails server -p 3001, the other is thin start (for some reason, if I just run rails server or thin start alone, they will only process incoming calls sequentially) .

Setting 1: The original attribute1 value in the database for the myID of interest is 3302. I fired one update call to the Heroku app (to update attribute1 to value 3303), then wait for about 5 seconds and fired another one to the Heroku app (to update attribute1 to value 3304). I was expecting the second call taking about 25 seconds to finish, because the first one took 15 seconds to finish due to the sleep 15 command I introduced in the code before mytable.save!, and the second call should be blocked at the line mytable = Mytables.find(:first, :conditions => ['"myID" = ?', myID], :lock => true ) for about 10 seconds, before it acquired the lock and then sleep for 15 seconds. But it turns out that the second call finished only about 5 seconds later than the first call.

And if I reverse the request order, i.e. first call is to update attribute1 to 3304 and the 5 second delayed second call is to update attribute1 to 3303, the final value would be 3303. Looking at the log on Heroku, the second call waited no time to acquire the lock while theoretically the first call is sleeping and thus still holding the lock.

Setting 2: Running two Thin rails server of the same app, one on port 3000 and one on port 3001. My understanding is that they connected to the same database and so if one instance of the server acquired a lock via SELECT FOR UPDATE, the other instance should not be able to acquire the lock and will be blocked. However, the locks behaviour is the same as on Heroku (not working as I intended). And because the servers are running locally, I managed to perform extra tweak test so that while the first call was sleeping for 15 seconds, I changed the code before launching the second call so that the 5-second-later second call only sleep for 1 second after acquiring the lock, and the second call did finish much earlier than the first call...

I also tried to use SELECT FOR UPDATE NOWAIT and introducing an extra line mytable.lock! immediately after the SELECT FOR UPDATE line, but the results are the same.

So it seems to me that while the SELECT FOR UPDATE command has been issued to the PostgreSQL table successfully, other thread/process can still SELECT FOR UPDATE the same row, and even UPDATE the same row without blocking at all...

I am completely baffled, and any suggestion would be welcomed. Thanks!

P.S.1 The reason for me to use a lock on the row is so that my code should be able to ensure that only calls to update the row to a higher attribute1 value would succeed.

P.S.2 Sample SQL output from the local log

"waiting for lock"
  Mytables Load (4.6ms)  SELECT "mytables".* FROM "mytables" WHERE ("myID" = 1935701094) LIMIT 1 FOR UPDATE
"acquired lock"
"woke up from sleep"
   (0.3ms)  BEGIN
   (1.5ms)  UPDATE "mytables" SET "attribute1" = 3304, "updated_at" = '2013-02-02 13:37:04.425577' WHERE "mytables"."id" = 40
   (0.4ms)  COMMIT
"done saving"

Answer 1

It turns out that because PostGreSQL has autocommit defaulted to be on, the line

Mytables Load (4.6ms)  SELECT "mytables".* FROM "mytables" WHERE ("myID" = 1935701094) LIMIT 1 FOR UPDATE

is actually followed by an automatically commit, hence releasing the lock.

I was mistaken when reading from this page http://api.rubyonrails.org/classes/ActiveRecord/Locking/Pessimistic.html that the

.find(____, :lock => true)

method automatically open a transaction, similar to

.with_lock(lock = true) 

covered in the end of the same page...

so to fix my Rails code, I just need to wrap it within a transaction, by adding

Mytables.transaction do 

under

begin

and add an extra "end" just before the "rescue" line.

The resulting SQL output would be something more like:

(0.3ms)  BEGIN
Mytables Load (4.6ms)  SELECT "mytables".* FROM "mytables" WHERE ("myID" = 1935701094) LIMIT 1 FOR UPDATE
(1.5ms)  UPDATE "mytables" SET "attribute1" = 3304, "updated_at" = '2013-02-02 13:37:04.425577' WHERE "mytables"."id" = 40
(0.4ms)  COMMIT