負荷テストしているときに、Deadlockの起きるはずのないところでDeadlockが起きたので、いろいろ調べた記録。
原因は、1つのTransaction内でupdateをかけてみて更新件数が0の場合、insertをするという操作をしているところでした。updateを行った際にそのKeyが存在しないと行ロックを広く取ってしまうことが原因みたいです。(あくまでらしいです。ソースコードなどまではおっていません。)
始めはO/R Mapper周りのバグかなと思ってたので、MySQL側の挙動であることを確定させるために検証コードも書いてみました。
ちなみに、Thread数が1ではこの問題は発生しません。
Sample code
App.scala
import java.sql.DriverManager
import scala.util.Random
object App{
def main(args : Array[String]) {
Class.forName("com.mysql.jdbc.Driver")
val con = DriverManager.getConnection("jdbc:mysql://localhost/test", username, password);
val st = con.createStatement()
st.executeUpdate("""drop table DeadLockCheck""")
st.executeUpdate("""create table if not exists DeadLockCheck(
id INT PRIMARY KEY,
c INT DEFAULT 0);""")
st.close()
con.close()
val threads = (0 until 5).map(i =>{
val t = new MyThread()
t.start()
t
})
threads.foreach(_.join)
}
}
object MyThread{
var random = new Random
}
class MyThread extends Thread{
override def run() = {
for(i <- 0 until 50){
val con = DriverManager.getConnection("jdbc:mysql://localhost/test", username, password);
con.setAutoCommit(false);
val st = con.createStatement()
val id = MyThread.random.nextInt.abs
if(st.executeUpdate("""update DeadLockCheck set c = c + 1 where id = %s""".format(id)) <= 0){
st.executeUpdate("""insert DeadLockCheck values(%s,1)""".format(id))
}
con.commit()
st.close()
con.close()
}
}
}
build.sbt
libraryDependencies += "mysql" % "mysql-connector-java" % "5.1.21"
結果
[info] Running App
[error] (Thread-82) com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
[error] (Thread-85) com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
[error] (Thread-84) com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1065)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2713)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1794)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1712)
at MyThread$$anonfun$run$1.apply$mcVI$sp(App.scala:43)
at scala.collection.immutable.Range.foreach$mVc$sp(Range.scala:75)
at MyThread.run(App.scala:36)
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1065)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2713)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1794)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1712)
at MyThread$$anonfun$run$1.apply$mcVI$sp(App.scala:43)
at scala.collection.immutable.Range.foreach$mVc$sp(Range.scala:75)
at MyThread.run(App.scala:36)
com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
at java.lang.reflect.Constructor.newInstance(Unknown Source)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1065)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2713)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1794)
at com.mysql.jdbc.StatementImpl.executeUpdate(StatementImpl.java:1712)
at MyThread$$anonfun$run$1.apply$mcVI$sp(App.scala:43)
at scala.collection.immutable.Range.foreach$mVc$sp(Range.scala:75)
at MyThread.run(App.scala:36)
[success] Total time: 1 s, completed 2012/08/06 19:01:10
参考
InnoDBのネクストキーロックによるデッドロックの例
