あえて実装し、解析することでバグを理解する (2) デッドロック(SQL) #Java

概要

WebアプリケーションがアクセスするRDBMSでデッドロックが発生したら、どのような事象が起きるでしょうか？

※この記事は、バグだらけのWebアプリケーションを使って、いろいろなバグとそれを解析する方法を紹介する記事の2回目です。

前回の記事では、Javaのデッドロックを再現させて、スレッドが停止して応答が返らなくなることを確認しました。RDBMSでのデッドロックも同様でしょうか？

実際に試してみましょう。

デッドロックを再現する

まずは、デッドロックを実際に再現してみましょう。Webアプリケーションをダウンロードして、起動します。起動方法はこちらを参照下さい。

※この記事では、バージョン1.2.22を使用して検証しています。今後のリリースで動作は変わる可能性があります。

起動したら次のURLにアクセスします。

http://localhost:8080

正常に起動していると、以下のような画面が表示されます。

この中にある「デッドロック(SQL)」と書かれたリンクをクリックすると、デッドロック(SQL)が再現可能な画面が表示されます。

画面の最下部に書かれている通り、この画面をもう1つのウインドウ(またはタブ)で開いて下さい。一方のウインドウでユーザーIDのリンクを一回クリックし、ユーザー一覧をIDで降順にソートします。そして、「更新」ボタンをクリックした直後に、もう一つのウインドウで昇順のまま「更新」ボタンをクリックします。

しばらくすると、一方のウインドウには、「10件更新しました。」のメッセージが表示され、もう一方には「デッドロックによりロックを取得できませんでした。」のメッセージが表示されます。この時、RDBMSではデッドロックが発生しています。

では、ログを確認してみましょう。logs/easybuggy.logを見ると、2つのスレッド(qtp1806431167-21、qtp1806431167-23)が交互にユーザー情報の更新を行い、前者がUSER04を、後者がUSER05を更新してから、20秒間の処理の停止が発生しています。その後、後者は処理が継続し、前者はSQLTransactionRollbackExceptionが発生しているのが分かります。

2017-04-24 13:21:26  INFO qtp1806431167-23 DeadlockServlet2 user09 is updated.
2017-04-24 13:21:26  INFO qtp1806431167-21 DeadlockServlet2 user00 is updated.
2017-04-24 13:21:26  INFO qtp1806431167-23 DeadlockServlet2 user08 is updated.
2017-04-24 13:21:26  INFO qtp1806431167-21 DeadlockServlet2 user01 is updated.
2017-04-24 13:21:27  INFO qtp1806431167-23 DeadlockServlet2 user07 is updated.
2017-04-24 13:21:27  INFO qtp1806431167-21 DeadlockServlet2 user02 is updated.
2017-04-24 13:21:27  INFO qtp1806431167-23 DeadlockServlet2 user06 is updated.
2017-04-24 13:21:27  INFO qtp1806431167-21 DeadlockServlet2 user03 is updated.
2017-04-24 13:21:28  INFO qtp1806431167-23 DeadlockServlet2 user05 is updated.
2017-04-24 13:21:28  INFO qtp1806431167-21 DeadlockServlet2 user04 is updated.
2017-04-24 13:21:48  INFO qtp1806431167-23 DeadlockServlet2 user04 is updated.
2017-04-24 13:21:48 ERROR qtp1806431167-21 DeadlockServlet2 SQLTransactionRollbackException occurs: 
java.sql.SQLTransactionRollbackException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, USERS, (1,16)
  Waiting XID : {198, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {194, X} 
Lock : ROW, USERS, (1,15)
  Waiting XID : {194, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {198, X} 
. The selected victim is XID : 198.
    at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
    at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
    at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
    at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
    at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
    at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
    at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
    at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
    at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(Unknown Source)
    at org.t246osslab.easybuggy.troubles.DeadlockServlet2.updateUsers(DeadlockServlet2.java:170)
    at org.t246osslab.easybuggy.troubles.DeadlockServlet2.service(DeadlockServlet2.java:55)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1507)
    at org.t246osslab.easybuggy.core.filters.SecurityFilter.doFilter(SecurityFilter.java:51)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
    at org.t246osslab.easybuggy.core.filters.EncodingFilter.doFilter(EncodingFilter.java:42)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
    at org.t246osslab.easybuggy.core.filters.AuthenticationFilter.doFilter(AuthenticationFilter.java:72)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1487)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:427)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
    at org.eclipse.jetty.server.Server.handle(Server.java:370)
    at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
    at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:984)
    at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1045)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:861)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:236)
    at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.sql.SQLException: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, USERS, (1,16)
  Waiting XID : {198, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {194, X} 
Lock : ROW, USERS, (1,15)
  Waiting XID : {194, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {198, X} 
. The selected victim is XID : 198.
    at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
    at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
    ... 42 more
Caused by: ERROR 40001: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : ROW, USERS, (1,16)
  Waiting XID : {198, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {194, X} 
Lock : ROW, USERS, (1,15)
  Waiting XID : {194, X} , APP, Update users set name = ?, phone = ?, mail = ? where id = ?
  Granted XID : {198, X} 
. The selected victim is XID : 198.
    at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
    at org.apache.derby.impl.services.locks.Deadlock.buildException(Unknown Source)
    at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
    at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
    at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
    at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source)
    at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
    at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
    at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown Source)
    at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown Source)
    at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown Source)
    at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown Source)
    at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(Unknown Source)
    at org.apache.derby.impl.sql.execute.TableScanResultSet.getNextRowCore(Unknown Source)
    at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(Unknown Source)
    at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown Source)
    at org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore(Unknown Source)
    at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(Unknown Source)
    at org.apache.derby.impl.sql.execute.UpdateResultSet.collectAffectedRows(Unknown Source)
    at org.apache.derby.impl.sql.execute.UpdateResultSet.open(Unknown Source)
    at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
    at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
    ... 36 more
2017-04-24 13:21:49  INFO qtp1806431167-23 DeadlockServlet2 user03 is updated.
2017-04-24 13:21:49  INFO qtp1806431167-23 DeadlockServlet2 user02 is updated.
2017-04-24 13:21:50  INFO qtp1806431167-23 DeadlockServlet2 user01 is updated.
2017-04-24 13:21:50  INFO qtp1806431167-23 DeadlockServlet2 user00 is updated.

どのような実装になっているのか

ソースコードはどのような実装になっていたのでしょうか？ログに出力されていたDeadlockServlet2.javaを見てみましょう。重要なのは以下の部分です。

    private String updateUsers(ArrayList<User> users, Locale locale) {

　　・・・(略)・・・

        try {

            conn = DBClient.getConnection();
            conn.setAutoCommit(false);

            stmt = conn.prepareStatement("Update users set name = ?, phone = ?, mail = ? where id = ?");
            for (User user : users) {
                stmt.setString(1, user.getName());
                stmt.setString(2, user.getPhone());
                stmt.setString(3, user.getMail());
                stmt.setString(4, user.getUserId());
                executeUpdate = executeUpdate + stmt.executeUpdate();
                Thread.sleep(500);
            }
            conn.commit();
            resultMessage = MessageUtils.getMsg("msg.update.records", new Object[] { executeUpdate }, locale) + "<br><br>";

        } catch (SQLTransactionRollbackException e) {
            resultMessage = MessageUtils.getErrMsg("msg.deadlock.occurs", locale);
            log.error("SQLTransactionRollbackException occurs: ", e);
            rollbak(conn);
　　・・・(略)・・・

    }

このサーブレットでは、画面上のユーザー一覧データを上から順に取得し、UPDATE文でRDBMSのユーザーレコードを更新しています。そして、全ての更新が終わるとコミットしています。

1つ目のスレッドがUSER05を更新し、次にUSER04を更新しようとしているときに、2つ目のスレッドがUSER04を更新し、次にUSER05を更新しようとして、お互いに完了を待つ状態になります。DB(Derby)はデッドロックが発生したことを検知して、20秒後に2つ目のスレッドのトランザクションに対してエラーを返します。これに対して、2つ目のスレッドは、SQLTransactionRollbackExceptionをキャッチして、例外処理を実施します。

他の設定、データベースではどうか

デッドロック時の動作は使用するRDBMSや設定にも依存します。今回使用しているRDBMSは、「インメモリデータベース」モードの組み込みDerbyで、デフォルトでは行レベルロックとなっています(※正確には、基本的に行レベルロックで、性能を考慮してロック粒度を複数行ロック、テーブルロックへと拡大します)。

テーブルレベルロックでの動作

Derbyの開発者ガイドを参照すると、derby.storage.rowLockingというオプションをfalseにすることで、行レベルロックをテーブルレベルロックにすることができます。

ということで、テーブルレベルロックの動作も検証してみます。pom.xmlに以下の行を変更します。

<!-- <argument>-Dderby.storage.rowLocking=true</argument> -->
<!-- 上の行の値をtrueからfalseに変更します -->
<argument>-Dderby.storage.rowLocking=false</argument>

EasyBuggyを再起動して、試してみましょう。mvnコマンド(mvn clean install exec:exec
)で起動している場合は、Ctrl+Cで停止して、再度同じコマンドで起動します。そして、もう一度ソート順を逆にした2つの一覧の更新を行います。今度はデッドロックは発生しないはずです。ログを確認してみると、以下のように最初に更新したスレッドの更新完了を待って、次のスレッドが更新を開始しています。

2017-04-24 13:51:50  INFO qtp1806431167-24 DeadlockServlet2 user09 is updated.
2017-04-24 13:51:50  INFO qtp1806431167-24 DeadlockServlet2 user08 is updated.
2017-04-24 13:51:51  INFO qtp1806431167-24 DeadlockServlet2 user07 is updated.
2017-04-24 13:51:51  INFO qtp1806431167-24 DeadlockServlet2 user06 is updated.
2017-04-24 13:51:52  INFO qtp1806431167-24 DeadlockServlet2 user05 is updated.
2017-04-24 13:51:52  INFO qtp1806431167-24 DeadlockServlet2 user04 is updated.
2017-04-24 13:51:53  INFO qtp1806431167-24 DeadlockServlet2 user03 is updated.
2017-04-24 13:51:53  INFO qtp1806431167-24 DeadlockServlet2 user02 is updated.
2017-04-24 13:51:54  INFO qtp1806431167-24 DeadlockServlet2 user01 is updated.
2017-04-24 13:51:54  INFO qtp1806431167-24 DeadlockServlet2 user00 is updated.
2017-04-24 13:51:55  INFO qtp1806431167-20 DeadlockServlet2 user00 is updated.
2017-04-24 13:51:56  INFO qtp1806431167-20 DeadlockServlet2 user01 is updated.
2017-04-24 13:51:56  INFO qtp1806431167-20 DeadlockServlet2 user02 is updated.
2017-04-24 13:51:57  INFO qtp1806431167-20 DeadlockServlet2 user03 is updated.
2017-04-24 13:51:57  INFO qtp1806431167-20 DeadlockServlet2 user04 is updated.
2017-04-24 13:51:58  INFO qtp1806431167-20 DeadlockServlet2 user05 is updated.
2017-04-24 13:51:58  INFO qtp1806431167-20 DeadlockServlet2 user06 is updated.
2017-04-24 13:51:59  INFO qtp1806431167-20 DeadlockServlet2 user07 is updated.
2017-04-24 13:51:59  INFO qtp1806431167-20 DeadlockServlet2 user08 is updated.
2017-04-24 13:52:00  INFO qtp1806431167-20 DeadlockServlet2 user09 is updated.

テーブルレベルのロックなので、既にロックを獲得済みのトランザクションがある場合は、その完了を待つことになります。完了後に更新するので、最初に更新したスレッドの更新内容は上書きされます。

MySQLでの動作

MySQLでも検証してみます。easybuggy/src/main/resources/application.propertiesのDerbyの設定をコメントアウトして、MySQLの設定を追加します。なお、今回使用したMySQLのバージョンは5.1.73です。

### RDBMS
# インメモリDBモードのDerbyの設定をコメントアウトして、
#database.url=jdbc:derby:memory:demo;create=true
#database.driver=org.apache.derby.jdbc.EmbeddedDriver
# MySQLの設定を追加
database.url=jdbc:mysql://localhost:3306/easybuggy?user=easybuggy&password=password
database.driver=com.mysql.jdbc.Driver

上の設定は、ローカルにインストールしたMySQLのeasybuggyデータベースにeasybuggyというユーザーで接続するための設定で、このユーザーのパスワードはpasswordです。

では、EasyBuggyを再起動して、試してみましょう。デッドロックは発生したでしょうか？私の環境では発生しませんでした。理由は、MySQLのデフォルトのストレージエンジンにあります。MySQLのバージョンが5.5より前の場合は、デフォルトのストレージエンジンが「MyISAM」になっています。

$ mysql -u root
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 31
Server version: 5.1.73-log Source distribution

Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> use information_schema;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> select table_name, engine from tables where table_schema = 'easybuggy';
+------------+--------+
| table_name | engine |
+------------+--------+
| users      | MyISAM |
+------------+--------+
1 row in set (0.00 sec)

MyISAMはテーブルレベルのロックのみで行レベルでのロックがサポートされていません。そこで/etc/my.cnfを編集してInnoDBに変更してみます。

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
symbolic-links=0
# 以下を追加
default-table-type=InnoDB

[mysqld_safe]
  …

変更したら、MySQL、EasyBuggyを再起動して、再度検証してみましょう。今度はデッドロックが発生すると思います。

2017-04-24 14:29:14  INFO qtp1806431167-22 DeadlockServlet2 user09 is updated.
2017-04-24 14:29:15  INFO qtp1806431167-22 DeadlockServlet2 user08 is updated.
2017-04-24 14:29:15  INFO qtp1806431167-25 DeadlockServlet2 user00 is updated.
2017-04-24 14:29:15  INFO qtp1806431167-22 DeadlockServlet2 user07 is updated.
2017-04-24 14:29:15  INFO qtp1806431167-25 DeadlockServlet2 user01 is updated.
2017-04-24 14:29:16  INFO qtp1806431167-22 DeadlockServlet2 user06 is updated.
2017-04-24 14:29:16  INFO qtp1806431167-25 DeadlockServlet2 user02 is updated.
2017-04-24 14:29:16  INFO qtp1806431167-22 DeadlockServlet2 user05 is updated.
2017-04-24 14:29:16  INFO qtp1806431167-25 DeadlockServlet2 user03 is updated.
2017-04-24 14:29:17  INFO qtp1806431167-22 DeadlockServlet2 user04 is updated.
2017-04-24 14:29:17  INFO qtp1806431167-22 DeadlockServlet2 user03 is updated.
2017-04-24 14:29:17 ERROR qtp1806431167-25 DeadlockServlet2 SQLTransactionRollbackException occurs:
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(NativeConstructorAccessorImpl.java:62)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
        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:1066)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4187)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4119)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2570)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2731)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2458)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2375)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2359)
        at org.t246osslab.easybuggy.troubles.DeadlockServlet2.updateUsers(DeadlockServlet2.java:169)
        at org.t246osslab.easybuggy.troubles.DeadlockServlet2.service(DeadlockServlet2.java:57)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:770)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1507)
        at org.t246osslab.easybuggy.core.filters.SecurityFilter.doFilter(SecurityFilter.java:51)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
        at org.t246osslab.easybuggy.core.filters.EncodingFilter.doFilter(EncodingFilter.java:42)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1495)
        at org.t246osslab.easybuggy.core.filters.AuthenticationFilter.doFilter(AuthenticationFilter.java:72)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1487)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:427)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
        at org.eclipse.jetty.server.Server.handle(Server.java:370)
        at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
        at org.eclipse.jetty.server.AbstractHttpConnection.content(AbstractHttpConnection.java:984)
        at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.content(AbstractHttpConnection.java:1045)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:861)
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:236)
        at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
        at java.lang.Thread.run(Thread.java:745)
2017-04-24 14:29:18  INFO qtp1806431167-22 DeadlockServlet2 user02 is updated.
2017-04-24 14:29:18  INFO qtp1806431167-22 DeadlockServlet2 user01 is updated.
2017-04-24 14:29:19  INFO qtp1806431167-22 DeadlockServlet2 user00 is updated.

ログを確認すると、java.sql.TransactionRollbackExceptionを継承したcom.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackExceptionがスローされていました。

また、Derbyではデッドロックを検出するまで20秒かかっていましたが、MySQLでは即時に検出しているようでした。これは、検出の方式やアルゴリズムの違いによるものだとと考えられます。詳しく調査していませんが、設定で変更できるのではないかと思います。

今回のまとめ

Javaのデッドロックのように、RDBMSでもロックの獲得順序が逆になる複数のスレッド(トランザクション)があると、デッドロックが発生する
Javaのデッドロックのように、永久に待ち続けることはない(一方の処理を継続し、もう一方がエラーとなる)
デッドロックが発生すると、JDBCドライバーはjava.sql.SQLTransactionRollbackExceptionをスローする(※JDBCドライバーの実装に依存する。バージョンが異なっていると、違う例外をスローする可能性がある)
デッドロック時の動作は使用するRDBMSとロックモードの設定に依存する
デッドロックが発生しないようにするには、データのアクセス順を決めてプログラムを実装する必要がある