MySQL Bugs: #43310: Transaction rollback (because of a deadlock) doesn't throw an Exception

Bug #43310	Transaction rollback (because of a deadlock) doesn't throw an Exception
Submitted:	2 Mar 2009 16:42	Modified:	31 Mar 2014 15:19
Reporter:	Michael Fink	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	Connector / J	Severity:	S2 (Serious)
Version:		OS:	Linux
Assigned to:	Alexander Soklakov	CPU Architecture:	Any
Tags:	deadlock, exception, hang, transaction

Description:
In my application multiple threads are querying the database. Sometimes a deadlock occures. Most of the time this raises an exception which I can catch and handle in my app. But sometimes the connector doesn't throw an exception which causes the thread to hang forever. The threads hangs at SocketInputStream.socketRead0. The only workaround is to set a socket timeout.

Here's the innodb monitor lock output:

------------------------
LATEST DETECTED DEADLOCK
------------------------
090302 17:02:24
*** (1) TRANSACTION:
TRANSACTION 0 7245, ACTIVE 2 sec, process no 32089, OS thread id 1157048656 inserting
mysql tables in use 1, locked 1
LOCK WAIT 53 lock struct(s), heap size 6752, 3304 row lock(s), undo log entries 58
MySQL thread id 138, query id 831920 localhost 127.0.0.1 loadbalancing update
insert into lb_counterData (time, value, counter) values ('2009-03-02 16:02:22', 3274908961, 981)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 337 n bits 624 index `counterData_counter_time_idx` of table `loadbalancing`.`lb_counterData` trx id 0 7245 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 10 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 80000000000003d6; asc         ;; 1: len 8; hex 80001245a3528e7f; asc    E R  ;; 2: len 8; hex 8000000000000170; asc        p;;

*** (2) TRANSACTION:
TRANSACTION 0 7246, ACTIVE 1 sec, process no 32089, OS thread id 1086032208 starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
97 lock struct(s), heap size 14320, 3172 row lock(s)
MySQL thread id 137, query id 832666 localhost 127.0.0.1 loadbalancing Sending data
select this_.id as id3_0_, this_.time as time3_0_, this_.value as value3_0_, this_.counter as counter3_0_ from lb_counterData this_ where this_.counter=805 order by this_.time desc limit 2
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 337 n bits 624 index `counterData_counter_time_idx` of table `loadbalancing`.`lb_counterData` trx id 0 7246 lock mode S locks gap before rec
Record lock, heap no 10 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 80000000000003d6; asc         ;; 1: len 8; hex 80001245a3528e7f; asc    E R  ;; 2: len 8; hex 8000000000000170; asc        p;;

Record lock, heap no 130 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 80000000000003dd; asc         ;; 1: len 8; hex 80001245a3528e7f; asc    E R  ;; 2: len 8; hex 800000000000015a; asc        Z;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 477 n bits 344 index `counterData_counter_time_idx` of table `loadbalancing`.`lb_counterData` trx id 0 7246 lock mode S waiting
Record lock, heap no 277 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 8000000000000325; asc        %;; 1: len 8; hex 80001245a352dd5e; asc    E R ^;; 2: len 8; hex 800000000000564d; asc       VM;;

*** WE ROLL BACK TRANSACTION (2)

And a stack trace:

	SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available [native method]	
	SocketInputStream.read(byte[], int, int) line: 129	
	ReadAheadInputStream.fill(int) line: 113	
	ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(byte[], int, int) line: 160	
	ReadAheadInputStream.read(byte[], int, int) line: 188	
	MysqlIO.readFully(InputStream, byte[], int, int) line: 2329	
	MysqlIO.nextRowFast(Field[], int, boolean, int, boolean, boolean, boolean) line: 1583	
	MysqlIO.nextRow(Field[], int, boolean, int, boolean, boolean, boolean, Buffer) line: 1375	
	MysqlIO.readSingleRowSet(long, int, int, boolean, Field[]) line: 2697	
	MysqlIO.getResultSet(StatementImpl, long, int, int, int, boolean, String, boolean, Field[]) line: 459	
	MysqlIO.readResultsForQueryOrUpdate(StatementImpl, int, int, int, boolean, String, Buffer, boolean, long, Field[]) line: 2411	
	MysqlIO.readAllResults(StatementImpl, int, int, int, boolean, String, Buffer, boolean, long, Field[]) line: 1657	
	MysqlIO.sqlQueryDirect(StatementImpl, String, String, Buffer, int, int, int, boolean, String, Field[]) line: 2036	
	JDBC4Connection(ConnectionImpl).execSQL(StatementImpl, String, int, Buffer, int, int, boolean, String, Field[], boolean) line: 2543	
	JDBC4PreparedStatement(PreparedStatement).executeInternal(int, Buffer, boolean, boolean, Field[], boolean) line: 1737	
	JDBC4PreparedStatement(PreparedStatement).executeQuery() line: 1888	
	NewProxyPreparedStatement.executeQuery() line: 76	
	BatchingBatcher(AbstractBatcher).getResultSet(PreparedStatement) line: 186	
	CriteriaLoader(Loader).getResultSet(PreparedStatement, boolean, boolean, RowSelection, SessionImplementor) line: 1787	
	CriteriaLoader(Loader).doQuery(SessionImplementor, QueryParameters, boolean) line: 674	
	CriteriaLoader(Loader).doQueryAndInitializeNonLazyCollections(SessionImplementor, QueryParameters, boolean) line: 236	
	CriteriaLoader(Loader).doList(SessionImplementor, QueryParameters) line: 2220	
	CriteriaLoader(Loader).listIgnoreQueryCache(SessionImplementor, QueryParameters) line: 2104	
	CriteriaLoader(Loader).list(SessionImplementor, QueryParameters, Set, Type[]) line: 2099	
	CriteriaLoader.list(SessionImplementor) line: 94	
	SessionImpl.list(CriteriaImpl) line: 1569	
	CriteriaImpl.list() line: 283	
	CounterDataDAO.getLatestData(Counter, int) line: 38
.
.
.

I've tested different versions of the connector (5.0 and 5.1) and the server (5.0 and 5.1). I've also tested the latest versions: connector 5.1.7 and server 5.1.31 (precompiled with intel compiler).

How to repeat:
---

Hi Michael and thanks for your report.

I do not see a test case attached nor, to be hones, do I see a bug here...
When storage engine returns error 'deadlock found. please restart transaction' you have exception in your program (SQLException, with a SQLState that starts with "08" to be precise).
When read hangs until other transaction(s) commit, connector is helpless. One can only set timeout in this case.

Tonci,

I think my interpretation and description of the problem was wrong.

Let me explain it again:

I've got two transactions in a deadlock situation. The first txn tries to INSERT and the second tries to SELECT some values. The DBMS recognizes the deadlock and decides to rollback the second txn.

Now from the applications point of view the method executeQuery() should return for the first tnx a ResultSet and for the second tnx it should throw an exception.

My problem is that sometimes executeQuery() for the second txn neither returns nor throws an exception. The root cause seems to be the  SocketInputStream.socketRead0 method which never returns (see my stacktrace).
The problem sporadically occurs only when the txn was rolled back by the DBMS. 

Do you agree with me that this is unexpected behavior?

Regards,
Michael

Michael, without repeatable test case I can not agree on anything so please attach a complete one.

> My problem is that sometimes executeQuery() for the second txn neither returns nor throws an exception. The root cause seems to be the SocketInputStream.socketRead0 method which never returns (see my stacktrace).
The problem sporadically occurs only when the txn was rolled back by the DBMS. 

Without test case I can't say more than I already said. Please check that transaction 2 was actually beaked in execution either by looking into general query log or WireShark or both. Reading such problem from stack traces is almost impossible.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Michael, it would be most interesting to see test case *and* stack trace of MySQL server at the time of hang. If I remember correctly, gdb has something like "thread apply all bt" that you can use. We are actually wondering at what client is waiting on...

Shyamsundar, why are your comments private? If there is nothing confidential in them, please remove the private flag so others can see.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

This bug occurs, if the any of the belowed tables have indexed columns and a lock is done on indexes.

Even though nobody bothered to attach a test case nor even table structures, I'm reopening this for further analysis.

Shyamsundar, your problem is described somewhere in BugsDB (I remember seeing it) tied to InnoDB. Please look for it.

@Michael:
Michael, it would be most interesting to see test case *and* stack trace of MySQL server at the time of hang. If I remember correctly, gdb has something like "thread apply all bt" that you can use. We are actually wondering at what client is waiting on...

Until such time this info is attached, and with no test case, I'm powerless.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

I close this report as "Can't repeat" because there is no feedback for a long time and several serious changes of c/J synchronization model were introduced since time this bug reported. Please, feel free to reopen it if the problem still exists in current driver.