[CONJ-398] Improve deadlock debugging capabilties

(cherry picked from commit a75555f)
mariadb-corporation · Feb 4, 2019 · c0ebfda · c0ebfda
1 parent a6a2eba
commit c0ebfda
Show file tree

Hide file tree

Showing 7 changed files with 187 additions and 37 deletions.
diff --git a/documentation/use-mariadb-connector-j-driver.creole b/documentation/use-mariadb-connector-j-driver.creole
@@ -187,6 +187,8 @@ See [[use-mariadb-connector-j-driver.creole#using-pooling|using pooling]] for mo
 |=autocommit|Set default autocommit value.\\//Default: true. Since 2.2.0//
 |=galeraAllowedState|Usually, Connection.isValid just send an empty packet to server, and server send a small response to ensure connectivity. When this option is set, connector will ensure Galera server state "wsrep_local_state" correspond to allowed values (separated by comma). example "4,5", recommended is "4". see [galera state](http://galeracluster.com/documentation-webpages/nodestates.html#node-state-changes) to know more..\\//Default: empty. Since 2.2.5//
 |=useAffectedRows|default correspond to the JDBC standard, reporting real affected rows. if enable, will report "affected" rows. example : if enable, an update command that doesn't change a row value will still be "affected", then report.\\//Default: false. Since 2.2.6//
+|=includeInnodbStatusInDeadlockExceptions|add "SHOW ENGINE INNODB STATUS" result to exception trace when having a deadlock exception\\//Default: false. Since 2.3.0//
+|=includeThreadDumpInDeadlockExceptions|add thread dump to exception trace when having a deadlock exception\\//Default: false. Since 2.3.0//
 
 \\\\
 == Failover/High availability URL parameters

diff --git a/src/main/java/org/mariadb/jdbc/MariaDbConnection.java b/src/main/java/org/mariadb/jdbc/MariaDbConnection.java
@@ -52,6 +52,35 @@
 
 package org.mariadb.jdbc;
 
+import java.net.SocketException;
+import java.sql.Array;
+import java.sql.Blob;
+import java.sql.CallableStatement;
+import java.sql.ClientInfoStatus;
+import java.sql.Clob;
+import java.sql.Connection;
+import java.sql.DatabaseMetaData;
+import java.sql.NClob;
+import java.sql.PreparedStatement;
+import java.sql.ResultSet;
+import java.sql.SQLClientInfoException;
+import java.sql.SQLException;
+import java.sql.SQLFeatureNotSupportedException;
+import java.sql.SQLNonTransientConnectionException;
+import java.sql.SQLPermission;
+import java.sql.SQLSyntaxErrorException;
+import java.sql.SQLWarning;
+import java.sql.SQLXML;
+import java.sql.Savepoint;
+import java.sql.Statement;
+import java.sql.Struct;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.Properties;
+import java.util.concurrent.Executor;
+import java.util.concurrent.locks.ReentrantLock;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
 import org.mariadb.jdbc.internal.logging.Logger;
 import org.mariadb.jdbc.internal.logging.LoggerFactory;
 import org.mariadb.jdbc.internal.protocol.Protocol;
@@ -65,16 +94,6 @@
 import org.mariadb.jdbc.internal.util.pool.GlobalStateInfo;
 import org.mariadb.jdbc.internal.util.pool.Pools;
 
-import java.net.SocketException;
-import java.sql.*;
-import java.util.HashMap;
-import java.util.Map;
-import java.util.Properties;
-import java.util.concurrent.Executor;
-import java.util.concurrent.locks.ReentrantLock;
-import java.util.regex.Matcher;
-import java.util.regex.Pattern;
-
 
 @SuppressWarnings("Annotator")
 public class MariaDbConnection implements Connection {
@@ -1690,4 +1709,12 @@ public void reset() throws SQLException {
 
         warningsCleared = true;
     }
+
+    public boolean includeDeadLockInfo() {
+        return options.includeInnodbStatusInDeadlockExceptions;
+    }
+
+    public boolean includeThreadsTraces() {
+        return options.includeInnodbStatusInDeadlockExceptions;
+    }
 }
diff --git a/src/main/java/org/mariadb/jdbc/internal/util/DefaultOptions.java b/src/main/java/org/mariadb/jdbc/internal/util/DefaultOptions.java
@@ -284,8 +284,11 @@ public enum DefaultOptions {
     USE_AFFECTED_ROWS("useAffectedRows", Boolean.FALSE, "1.8.0", "If false (default), use \"found rows\" for the row "
             + "count of statements. This corresponds to the JDBC standard.\n"
             + "If true, use \"affected rows\" for the row count.\n"
-            + "This changes the behavior of, for example, UPDATE... ON DUPLICATE KEY statements.", false);
-
+            + "This changes the behavior of, for example, UPDATE... ON DUPLICATE KEY statements.", false),
+    INCLUDE_STATUS("includeInnodbStatusInDeadlockExceptions", Boolean.FALSE, "1.8.0",
+        "add \"SHOW ENGINE INNODB STATUS\" result to exception trace when having a deadlock exception", false),
+    INCLUDE_THREAD_DUMP("includeThreadDumpInDeadlockExceptions", Boolean.FALSE, "1.8.0",
+        "add thread dump to exception trace when having a deadlock exception", false);
 
     private final String optionName;
     private final String description;

diff --git a/src/main/java/org/mariadb/jdbc/internal/util/LogQueryTool.java b/src/main/java/org/mariadb/jdbc/internal/util/LogQueryTool.java
@@ -52,14 +52,13 @@
 
 package org.mariadb.jdbc.internal.util;
 
-import org.mariadb.jdbc.internal.com.send.parameters.ParameterHolder;
-import org.mariadb.jdbc.internal.util.dao.PrepareResult;
+import static org.mariadb.jdbc.internal.util.SqlStates.CONNECTION_EXCEPTION;
 
 import java.net.SocketTimeoutException;
 import java.nio.ByteBuffer;
 import java.sql.SQLException;
-
-import static org.mariadb.jdbc.internal.util.SqlStates.CONNECTION_EXCEPTION;
+import org.mariadb.jdbc.internal.com.send.parameters.ParameterHolder;
+import org.mariadb.jdbc.internal.util.dao.PrepareResult;
 
 public class LogQueryTool {
     private final Options options;
@@ -115,8 +114,11 @@ public SQLException exceptionWithQuery(String sql, SQLException sqlException, bo
         }
 
         if (options.dumpQueriesOnException || sqlException.getErrorCode() == 1064) {
-            return new SQLException(sqlException.getMessage() + "\nQuery is: " + subQuery(sql), sqlException.getSQLState(),
-                    sqlException.getErrorCode(), sqlException.getCause());
+            return new SQLException(sqlException.getMessage()
+                + "\nQuery is: " + subQuery(sql)
+                + "\njava thread: " + Thread.currentThread().getName(),
+                sqlException.getSQLState(),
+                sqlException.getErrorCode(), sqlException.getCause());
         }
         return sqlException;
     }
@@ -165,13 +167,13 @@ public SQLException exceptionWithQuery(ParameterHolder[] parameters, SQLExceptio
     public SQLException exceptionWithQuery(SQLException sqlEx, PrepareResult prepareResult) {
         if (options.dumpQueriesOnException || sqlEx.getErrorCode() == 1064) {
             String querySql = prepareResult.getSql();
-
             String message = sqlEx.getMessage();
             if (options.maxQuerySizeToLog != 0 && querySql.length() > options.maxQuerySizeToLog - 3) {
                 message += "\nQuery is: " + querySql.substring(0, options.maxQuerySizeToLog - 3) + "...";
             } else {
                 message += "\nQuery is: " + querySql;
             }
+            message += "\njava thread: " + Thread.currentThread().getName();
             return new SQLException(message, sqlEx.getSQLState(), sqlEx.getErrorCode(), sqlEx.getCause());
         }
         return sqlEx;
@@ -200,9 +202,13 @@ private String exWithQuery(String message, PrepareResult serverPrepareResult, Pa
             }
 
             if (options.maxQuerySizeToLog != 0 && sql.length() > options.maxQuerySizeToLog - 3) {
-                return message + "\nQuery is: " + sql.substring(0, options.maxQuerySizeToLog - 3) + "...";
+                return message
+                    + "\nQuery is: " + sql.substring(0, options.maxQuerySizeToLog - 3) + "..."
+                    + "\njava thread: " + Thread.currentThread().getName();
             } else {
-                return message + "\nQuery is: " + sql;
+                return message
+                    + "\nQuery is: " + sql
+                    + "\njava thread: " + Thread.currentThread().getName();
             }
         }
         return message;

diff --git a/src/main/java/org/mariadb/jdbc/internal/util/Options.java b/src/main/java/org/mariadb/jdbc/internal/util/Options.java
@@ -122,6 +122,8 @@ public class Options implements Cloneable {
     public boolean useBulkStmts;
     public boolean disableSslHostnameVerification;
     public boolean autocommit = true;
+    public boolean includeInnodbStatusInDeadlockExceptions;
+    public boolean includeThreadDumpInDeadlockExceptions;
 
     //logging options
     public boolean log;
@@ -212,6 +214,8 @@ public boolean equals(Object obj) {
         if (cacheCallableStmts != opt.cacheCallableStmts) return false;
         if (useBatchMultiSendNumber != opt.useBatchMultiSendNumber) return false;
         if (enablePacketDebug != opt.enablePacketDebug) return false;
+        if (includeInnodbStatusInDeadlockExceptions != opt.includeInnodbStatusInDeadlockExceptions) return false;
+        if (includeThreadDumpInDeadlockExceptions != opt.includeThreadDumpInDeadlockExceptions) return false;
         if (useBulkStmts != opt.useBulkStmts) return false;
         if (disableSslHostnameVerification != opt.disableSslHostnameVerification) return false;
         if (log != opt.log) return false;
@@ -340,6 +344,8 @@ public int hashCode() {
         result = 31 * result + useBatchMultiSendNumber;
         result = 31 * result + (usePipelineAuth != null ? usePipelineAuth.hashCode() : 0);
         result = 31 * result + (enablePacketDebug ? 1 : 0);
+        result = 31 * result + (includeInnodbStatusInDeadlockExceptions ? 1 : 0);
+        result = 31 * result + (includeThreadDumpInDeadlockExceptions ? 1 : 0);
         result = 31 * result + (useBulkStmts ? 1 : 0);
         result = 31 * result + (disableSslHostnameVerification ? 1 : 0);
         result = 31 * result + (log ? 1 : 0);

diff --git a/src/main/java/org/mariadb/jdbc/internal/util/exceptions/ExceptionMapper.java b/src/main/java/org/mariadb/jdbc/internal/util/exceptions/ExceptionMapper.java
@@ -52,14 +52,25 @@
 
 package org.mariadb.jdbc.internal.util.exceptions;
 
+import static org.mariadb.jdbc.internal.util.SqlStates.CONNECTION_EXCEPTION;
+
+import java.sql.ResultSet;
+import java.sql.SQLDataException;
+import java.sql.SQLException;
+import java.sql.SQLFeatureNotSupportedException;
+import java.sql.SQLIntegrityConstraintViolationException;
+import java.sql.SQLInvalidAuthorizationSpecException;
+import java.sql.SQLNonTransientConnectionException;
+import java.sql.SQLSyntaxErrorException;
+import java.sql.SQLTimeoutException;
+import java.sql.SQLTransactionRollbackException;
+import java.sql.SQLTransientException;
+import java.sql.SQLWarning;
+import java.sql.Statement;
 import org.mariadb.jdbc.MariaDbConnection;
 import org.mariadb.jdbc.MariaDbStatement;
 import org.mariadb.jdbc.internal.util.SqlStates;
 
-import java.sql.*;
-
-import static org.mariadb.jdbc.internal.util.SqlStates.CONNECTION_EXCEPTION;
-
 
 public class ExceptionMapper {
 
@@ -95,19 +106,60 @@ public static SQLException connException(String message, Throwable cause) {
      */
     public static SQLException getException(SQLException exception, MariaDbConnection connection,
                                             MariaDbStatement statement, boolean timeout) {
-        String message = exception.getMessage();
+        final StringBuilder message;
+        String errMsg = exception.getMessage();
+        if (errMsg.contains("\n")) errMsg = errMsg.substring(0, errMsg.indexOf("\n"));
         if (connection != null) {
-            message = "(conn=" + connection.getServerThreadId() + ") " + message;
+            message = new StringBuilder("(conn=")
+                .append(connection.getServerThreadId())
+                .append(") ")
+                .append(errMsg);
         } else if (statement != null) {
-            message = "(conn=" + statement.getServerThreadId() + ") " + message;
+            message = new StringBuilder("(conn=")
+                .append(statement.getServerThreadId())
+                .append(") ")
+                .append(errMsg);
+        } else {
+            message = new StringBuilder(errMsg);
         }
 
         SQLException sqlException;
         SqlStates state = null;
 
         if (exception.getSQLState() != null) {
-            if (message.contains("\n")) message = message.substring(0, message.indexOf("\n"));
-            sqlException = get(message, exception.getSQLState(), exception.getErrorCode(), exception, timeout);
+            if (connection != null
+                && exception.getSQLState() != null
+                && (1205 == exception.getErrorCode() || 1614 == exception.getErrorCode())) {
+
+                if (connection.includeDeadLockInfo()) {
+                    try {
+                        Statement stmt = connection.createStatement();
+                        ResultSet rs = stmt.executeQuery("SHOW ENGINE INNODB STATUS");
+                        if (rs.next()) {
+                            message.append("\ndeadlock information: ")
+                                .append(rs.getString(3));
+                        }
+                    } catch (SQLException sqle) {
+                        //eat
+                    }
+                }
+
+                if (connection.includeThreadsTraces()) {
+                    message.append("\n\ncurrent threads: ");
+                    Thread.getAllStackTraces().forEach((thread, traces) -> {
+                        message.append("\n  name:\"")
+                            .append(thread.getName())
+                            .append("\" pid:")
+                            .append(thread.getId())
+                            .append(" status:")
+                            .append(thread.getState());
+                        for (int i = 0; i < traces.length; i++) {
+                            message.append("\n    ").append(traces[i]);
+                        }
+                    });
+                }
+            }
+            sqlException = get(message.toString(), exception.getSQLState(), exception.getErrorCode(), exception, timeout);
             String sqlState = exception.getSQLState();
             state = SqlStates.fromString(sqlState);
             SQLException nextException = exception.getNextException();

diff --git a/src/test/java/org/mariadb/jdbc/StatementTest.java b/src/test/java/org/mariadb/jdbc/StatementTest.java
@@ -52,17 +52,26 @@
 
 package org.mariadb.jdbc;
 
-import org.junit.Assume;
-import org.junit.BeforeClass;
-import org.junit.Test;
+import static org.hamcrest.CoreMatchers.equalTo;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertThat;
+import static org.junit.Assert.assertTrue;
+import static org.junit.Assert.fail;
 
 import java.io.ByteArrayInputStream;
 import java.io.UnsupportedEncodingException;
-import java.sql.*;
+import java.sql.Connection;
+import java.sql.DriverManager;
+import java.sql.PreparedStatement;
+import java.sql.ResultSet;
+import java.sql.SQLException;
+import java.sql.Statement;
+import java.sql.Timestamp;
 import java.util.Properties;
-
-import static org.hamcrest.CoreMatchers.equalTo;
-import static org.junit.Assert.*;
+import org.junit.Assume;
+import org.junit.BeforeClass;
+import org.junit.Test;
 
 public class StatementTest extends BaseTest {
 
@@ -455,4 +464,49 @@ public void testProperBatchUpdate() throws SQLException {
         assertFalse(rs.next());
 
     }
+
+    @Test
+    public void deadLockInformation() throws SQLException {
+      createTable("deadlock", "a int primary key", "engine=innodb");
+      Statement stmt = sharedConnection.createStatement();
+      stmt.execute("insert into deadlock(a) values(0), (1)");
+      Connection conn1 = null;
+      try {
+        conn1 = setConnection(
+            "&includeInnodbStatusInDeadlockExceptions&includeThreadDumpInDeadlockExceptions");
+        conn1.setTransactionIsolation(Connection.TRANSACTION_SERIALIZABLE);
+        Statement stmt1 = conn1.createStatement();
+        try {
+            stmt1.execute("SET SESSION idle_transaction_timeout=2");
+        } catch (SQLException e) {
+            //eat ( for mariadb >= 10.3)
+        }
+        stmt.execute("start transaction");
+        stmt.execute("update deadlock set a = 2 where a <> 0");
+        Connection conn2 = null;
+        try {
+          conn2 = setConnection(
+              "&includeInnodbStatusInDeadlockExceptions&includeThreadDumpInDeadlockExceptions");
+          Statement stmt2 = conn2.createStatement();
+          conn2.setTransactionIsolation(Connection.TRANSACTION_SERIALIZABLE);
+          try {
+              stmt2.execute("SET SESSION idle_transaction_timeout=2");
+          } catch (SQLException e) {
+              //eat ( for mariadb >= 10.3)
+          }
+          stmt2.execute("start transaction");
+          try {
+              stmt2.execute("update deadlock set a = 3 where a <> 1");
+              fail("Must have thrown deadlock exception");
+          } catch (SQLException sqle) {
+              assertTrue(sqle.getMessage().contains("current threads:"));
+              assertTrue(sqle.getMessage().contains("END OF INNODB MONITOR OUTPUT"));
+          }
+        } finally {
+          if (conn2 != null) conn2.close();
+        }
+      } finally {
+        if (conn1 != null) conn1.close();
+      }
+    }
 }