Grails
  1. Grails
  2. GRAILS-8433

Behaviour change for locks and/or transactions between 1.3.7 and 2.0.0.RCx

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0-RC3
    • Fix Version/s: 2.0.4
    • Component/s: Persistence
    • Labels:
    • Environment:
      MBP
      OS X 10.6

      Description

      There seems to be a change in the way locks and/or transactions work when handling concurrent requests.
      I've created a test app (Bank Of Grails) to demonstrate the issue on both Grails 1.3.7 and Grails 2.0.0.RCx.
      You will need Apache Bench (AB) to test them
      You can get the code from github:
      https://github.com/domiko/bog200 for Grails 2.0.0
      https://github.com/domiko/bog137 for Grails 1.3.7

      Non-generated code is identical in both versions.

      Build the projects and run
      ab -n 1000 -c 100 http://localhost:8080/bog200/teller/randomTransfer
      OR
      ab -n 1000 -c 100 http://localhost:8080/bog137/teller/randomTransfer

      The 1.3.7 version works while the 2.0.0 version throws StaleObjectStateException exceptions.

      Rgds,
      Dominique.

        Issue Links

          Activity

          Hide
          Dominique Bitau Kongolo added a comment -

          Forgot to mention, the projects also require MySQL with a database named bog.

          Show
          Dominique Bitau Kongolo added a comment - Forgot to mention, the projects also require MySQL with a database named bog.
          Hide
          Graeme Rocher added a comment -

          Caused by this bug in Hibernate https://hibernate.onjira.com/browse/HHH-5275 present since Hibernate 3.5

          Work around is to use HQL for the query

          Show
          Graeme Rocher added a comment - Caused by this bug in Hibernate https://hibernate.onjira.com/browse/HHH-5275 present since Hibernate 3.5 Work around is to use HQL for the query
          Hide
          Graeme Rocher added a comment -

          There is no solution to this issue until the Hibernate team fix the relevant Hibernate bug. I am in contact with them to try and address it, but in the meantime I suggest users vote for the associated Hibernate issue.

          Show
          Graeme Rocher added a comment - There is no solution to this issue until the Hibernate team fix the relevant Hibernate bug. I am in contact with them to try and address it, but in the meantime I suggest users vote for the associated Hibernate issue.
          Hide
          Lari Hotari added a comment -

          I think there should be a note about this issue in the release notes ("known issues").

          It seems that the workaround is to call .lock() on the instance?
          HHH-5275 seems to affect only criterias and queries.

          Show
          Lari Hotari added a comment - I think there should be a note about this issue in the release notes ("known issues"). It seems that the workaround is to call .lock() on the instance? HHH-5275 seems to affect only criterias and queries.
          Hide
          Graeme Rocher added a comment -

          The workaround is use HQL when requiring locking in a query. Not nice, but the Hibernate guys don't intend to back port the fix to 3.x so not much we can do

          Show
          Graeme Rocher added a comment - The workaround is use HQL when requiring locking in a query. Not nice, but the Hibernate guys don't intend to back port the fix to 3.x so not much we can do
          Hide
          Graeme Rocher added a comment -

          Actually it does appear that is was back ported to 3.6.10 so there is hope

          Show
          Graeme Rocher added a comment - Actually it does appear that is was back ported to 3.6.10 so there is hope
          Hide
          Lari Hotari added a comment -

          Oh yes, there is https://hibernate.onjira.com/browse/HHH-6988 for the back port.

          Show
          Lari Hotari added a comment - Oh yes, there is https://hibernate.onjira.com/browse/HHH-6988 for the back port.
          Hide
          Lari Hotari added a comment -

          I think this problem is solved in Hibernate 3.6.10 . I re-tested with Grails 2.0.3 but I had to modify the test app a bit because of bug GRAILS-8988

          The H2 url had to be changed too:
          url = "jdbc:h2:prodDb;MVCC=TRUE;LOCK_TIMEOUT=30000"

          lock timeout is 1 second by default in H2.

          Show
          Lari Hotari added a comment - I think this problem is solved in Hibernate 3.6.10 . I re-tested with Grails 2.0.3 but I had to modify the test app a bit because of bug GRAILS-8988 The H2 url had to be changed too: url = "jdbc:h2:prodDb;MVCC=TRUE;LOCK_TIMEOUT=30000" lock timeout is 1 second by default in H2.
          Hide
          Lari Hotari added a comment -

          No it's not fixed. Tested with mysql and I get some StaleObjectStateExceptions.

          Show
          Lari Hotari added a comment - No it's not fixed. Tested with mysql and I get some StaleObjectStateExceptions.
          Hide
          Graeme Rocher added a comment -

          Lari - did you test with InnoDB tables? The key question is whether the SQL statements have "..FOR UPDATE" on them

          Show
          Graeme Rocher added a comment - Lari - did you test with InnoDB tables? The key question is whether the SQL statements have "..FOR UPDATE" on them
          Hide
          Lari Hotari added a comment -

          I checked that the tables are in InnoDb and sql statements have ".. for update". This time I didn't get StaleObjectStateExceptions .

          Show
          Lari Hotari added a comment - I checked that the tables are in InnoDb and sql statements have ".. for update". This time I didn't get StaleObjectStateExceptions .
          Hide
          Graeme Rocher added a comment -

          Thanks for confirming

          Show
          Graeme Rocher added a comment - Thanks for confirming
          Hide
          Lari Hotari added a comment -

          I tested once more and this time I'm getting the StaleObjectStateExceptions again. The SQL statements are correct.

          I've enabled mysql query logging:

          [server]
          general_log=1
          general_log_file=/var/log/mysql/query.log
          

          Log example of sql statements (for a single transaction):

                             81 Query     SET autocommit=0
                             81 Query     select this_.id as id0_0_, this_.version as version0_0_, this_.account_number as account
          3_0_0_, this_.balance as balance0_0_, this_.date_created as date5_0_0_, this_.last_updated as last6_0_0_, this_.name as 
          name0_0_, this_.status as status0_0_, this_.total_in as total9_0_0_, this_.total_out as total10_0_0_, this_.transf_in_co
          unt as transf11_0_0_, this_.transf_out_count as transf12_0_0_ from account this_ where this_.account_number='1234703' li
          mit 1 for update
                             81 Query     select this_.id as id0_0_, this_.version as version0_0_, this_.account_number as account3_0_0_, this_.balance as balance0_0_, this_.date_created as date5_0_0_, this_.last_updated as last6_0_0_, this_.name as name0_0_, this_.status as status0_0_, this_.total_in as total9_0_0_, this_.total_out as total10_0_0_, this_.transf_in_count as transf11_0_0_, this_.transf_out_count as transf12_0_0_ from account this_ where this_.account_number='1234800' limit 1 for update
                             81 Query     insert into transfer (version, amount, date_created, dst_account, last_updated, src_account) values (0, 5.0, '2012-04-17 08:09:49', '1234703', '2012-04-17 08:09:49', '1234800')
                             81 Query     update account set version=39, account_number='1234703', balance=237.0, date_created='2012-04-16 16:43:22', last_updated='2012-04-17 08:09:49', name='Earline Dietrich', status='OK', total_in=105.0, total_out=118.0, transf_in_count=0, transf_out_count=0 where id=1362 and version=38
                             81 Query     update account set version=39, account_number='1234800', balance=240.0, date_created='2012-04-16 16:43:24', last_updated='2012-04-17 08:09:49', name='Kailey Reynolds', status='OK', total_in=102.0, total_out=112.0, transf_in_count=0, transf_out_count=0 where id=2332 and version=38
                             81 Query     commit
                             81 Query     SET autocommit=1
          

          I've checked that InnoDB is engine with these commands:

          show create table account;
          show create table transfer;
          
          Show
          Lari Hotari added a comment - I tested once more and this time I'm getting the StaleObjectStateExceptions again. The SQL statements are correct. I've enabled mysql query logging: [server] general_log=1 general_log_file=/ var /log/mysql/query.log Log example of sql statements (for a single transaction): 81 Query SET autocommit=0 81 Query select this_.id as id0_0_, this_.version as version0_0_, this_.account_number as account 3_0_0_, this_.balance as balance0_0_, this_.date_created as date5_0_0_, this_.last_updated as last6_0_0_, this_.name as name0_0_, this_.status as status0_0_, this_.total_in as total9_0_0_, this_.total_out as total10_0_0_, this_.transf_in_co unt as transf11_0_0_, this_.transf_out_count as transf12_0_0_ from account this_ where this_.account_number='1234703' li mit 1 for update 81 Query select this_.id as id0_0_, this_.version as version0_0_, this_.account_number as account3_0_0_, this_.balance as balance0_0_, this_.date_created as date5_0_0_, this_.last_updated as last6_0_0_, this_.name as name0_0_, this_.status as status0_0_, this_.total_in as total9_0_0_, this_.total_out as total10_0_0_, this_.transf_in_count as transf11_0_0_, this_.transf_out_count as transf12_0_0_ from account this_ where this_.account_number='1234800' limit 1 for update 81 Query insert into transfer (version, amount, date_created, dst_account, last_updated, src_account) values (0, 5.0, '2012-04-17 08:09:49', '1234703', '2012-04-17 08:09:49', '1234800') 81 Query update account set version=39, account_number='1234703', balance=237.0, date_created='2012-04-16 16:43:22', last_updated='2012-04-17 08:09:49', name='Earline Dietrich', status='OK', total_in=105.0, total_out=118.0, transf_in_count=0, transf_out_count=0 where id=1362 and version=38 81 Query update account set version=39, account_number='1234800', balance=240.0, date_created='2012-04-16 16:43:24', last_updated='2012-04-17 08:09:49', name='Kailey Reynolds', status='OK', total_in=102.0, total_out=112.0, transf_in_count=0, transf_out_count=0 where id=2332 and version=38 81 Query commit 81 Query SET autocommit=1 I've checked that InnoDB is engine with these commands: show create table account; show create table transfer;
          Hide
          Lari Hotari added a comment -

          There is something strange going on since after changing DataSource.groovy and setting defaultIsolationLevel to java.sql.Connection.TRANSACTION_READ_COMMITTED I get a lot of "com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction" exceptions.

          I also tried REPEATABLE_READ, but that gives StaleObjectStateExceptions too.

                       properties {
                          defaultTransactionIsolation = java.sql.Connection.TRANSACTION_REPEATABLE_READ
                       }
          

          This doesn't seem to be a Grails/Hibernate problem since the SQL statements are what we are expecting.
          It could be some Mysql setting that causes the problem (or the application logic isn't correct, I'm suspecting that the both accounts should be locked with the same sql statement.)

          Show
          Lari Hotari added a comment - There is something strange going on since after changing DataSource.groovy and setting defaultIsolationLevel to java.sql.Connection.TRANSACTION_READ_COMMITTED I get a lot of "com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction" exceptions. I also tried REPEATABLE_READ, but that gives StaleObjectStateExceptions too. properties { defaultTransactionIsolation = java.sql.Connection.TRANSACTION_REPEATABLE_READ } This doesn't seem to be a Grails/Hibernate problem since the SQL statements are what we are expecting. It could be some Mysql setting that causes the problem (or the application logic isn't correct, I'm suspecting that the both accounts should be locked with the same sql statement.)
          Hide
          Lari Hotari added a comment -

          This isolation level works correctly:

          properties {
              defaultTransactionIsolation = java.sql.Connection.TRANSACTION_SERIALIZABLE
          }
          
          Show
          Lari Hotari added a comment - This isolation level works correctly: properties { defaultTransactionIsolation = java.sql.Connection.TRANSACTION_SERIALIZABLE }
          Hide
          Lari Hotari added a comment -

          Adding "cache:false" to these rows in AccountManagerService fixes the problem.

          				if(src < dst) {
          					srcAcc = Account.findByAccountNumber(src, [lock:true, cache:false])
          					dstAcc = Account.findByAccountNumber(dst, [lock:true, cache:false])
          				} else {
          					dstAcc = Account.findByAccountNumber(dst, [lock:true, cache:false])
          					srcAcc = Account.findByAccountNumber(src, [lock:true, cache:false])
          				}
          

          We should make sure on Grails side that queries are never cached by default if lock=true is specified for the query.

          Show
          Lari Hotari added a comment - Adding "cache:false" to these rows in AccountManagerService fixes the problem. if (src < dst) { srcAcc = Account.findByAccountNumber(src, [lock: true , cache: false ]) dstAcc = Account.findByAccountNumber(dst, [lock: true , cache: false ]) } else { dstAcc = Account.findByAccountNumber(dst, [lock: true , cache: false ]) srcAcc = Account.findByAccountNumber(src, [lock: true , cache: false ]) } We should make sure on Grails side that queries are never cached by default if lock=true is specified for the query.
          Hide
          Lari Hotari added a comment -

          oops, too early to say. again I'm getting the exceptions...

          Adding this line fixes the problem:
          Account.findAllByAccountNumberOrAccountNumber(src, dst, [lock:true, cache:false])

          That locks both accounts at once, but is that required?

          Show
          Lari Hotari added a comment - oops, too early to say. again I'm getting the exceptions... Adding this line fixes the problem: Account.findAllByAccountNumberOrAccountNumber(src, dst, [lock:true, cache:false] ) That locks both accounts at once, but is that required?
          Hide
          Lari Hotari added a comment -

          I can now confirm that modifying this setting in Config.groovy fixes the problem:

          grails.hibernate.cache.queries = false
          

          I think that the fix should be that queries are never cached if lock=true is specified for a query.

          Show
          Lari Hotari added a comment - I can now confirm that modifying this setting in Config.groovy fixes the problem: grails.hibernate.cache.queries = false I think that the fix should be that queries are never cached if lock=true is specified for a query.
          Hide
          Lari Hotari added a comment -

          I reopened this issue. It might be better to create a new issue for the "grails.hibernate.cache.queries" issue and close this one after that has been done.

          Show
          Lari Hotari added a comment - I reopened this issue. It might be better to create a new issue for the "grails.hibernate.cache.queries" issue and close this one after that has been done.
          Hide
          Dominique Bitau Kongolo added a comment -

          <<Lari Hotari >>
          Adding this line fixes the problem:
          Account.findAllByAccountNumberOrAccountNumber(src, dst, [lock:true, cache:false])

          That locks both accounts at once, but is that required?
          <<Lari Hotari>>

          Don't know (yet, I'm gonna test this evening) if it fixes the issue but it's certainly a good idea to lock both accounts in one database roundtrip. Nice trick.

          Show
          Dominique Bitau Kongolo added a comment - <<Lari Hotari >> Adding this line fixes the problem: Account.findAllByAccountNumberOrAccountNumber(src, dst, [lock:true, cache:false] ) That locks both accounts at once, but is that required? <<Lari Hotari>> Don't know (yet, I'm gonna test this evening) if it fixes the issue but it's certainly a good idea to lock both accounts in one database roundtrip. Nice trick.
          Hide
          Lari Hotari added a comment -

          This wasn't required to fix the issue. Look at the fixing commit to see the details of the bug:
          https://github.com/grails/grails-core/commit/3853dd2dcc317452321a5c31d5774db82cfd1409
          (disable query cache when lock=true; make it possible to disable caching for a query)

          Show
          Lari Hotari added a comment - This wasn't required to fix the issue. Look at the fixing commit to see the details of the bug: https://github.com/grails/grails-core/commit/3853dd2dcc317452321a5c31d5774db82cfd1409 (disable query cache when lock=true; make it possible to disable caching for a query)
          Hide
          Lari Hotari added a comment -

          Yes and Hibernate 3.6.10 was also required (that was included already in 2.0.3)

          Show
          Lari Hotari added a comment - Yes and Hibernate 3.6.10 was also required (that was included already in 2.0.3)

            People

            • Assignee:
              Lari Hotari
              Reporter:
              Dominique Bitau Kongolo
            • Votes:
              2 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Last Reviewed:

                Development