Bug #24995 Socket read locks up other threads
Submitted: 12 Dec 2006 7:57 Modified: 8 Dec 2014 7:30
Reporter: [ name withheld ] Email Updates:
Status: Duplicate Impact on me:
None 
Category:Connector / J Severity:S2 (Serious)
Version:5.0.4 OS:Linux (Ubuntu Linux)
Assigned to: Alexander Soklakov CPU Architecture:Any

[12 Dec 2006 7:57] [ name withheld ]
Description:
In a multi threaded application, in which many threads want to access the database, there's one thread who gets stuck at a socket read. Here's a stack trace of that thread obtained with jstack:

- java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
 - java.net.SocketInputStream.read(byte[], int, int) @bci=84, line=129 (Compiled frame)
 - com.mysql.jdbc.util.ReadAheadInputStream.fill(int) @bci=262, line=113 (Compiled frame)
 - com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(byte[], int, int) @bci=176, line=160 (Compiled frame)
 - com.mysql.jdbc.util.ReadAheadInputStream.read(byte[], int, int) @bci=48, line=188 (Compiled frame)
 - com.mysql.jdbc.MysqlIO.readFully(java.io.InputStream, byte[], int, int) @bci=34, line=1910 (Compiled frame)
 - com.mysql.jdbc.MysqlIO.reuseAndReadPacket(com.mysql.jdbc.Buffer) @bci=16, line=2304 (Compiled frame)
 - com.mysql.jdbc.MysqlIO.checkErrorPacket(int) @bci=14, line=2803 (Compiled frame)
 - com.mysql.jdbc.MysqlIO.sendCommand(int, java.lang.String, com.mysql.jdbc.Buffer, boolean, java.lang.String) @bci=360, line=1573 (Compiled frame)
 - com.mysql.jdbc.MysqlIO.sqlQueryDirect(com.mysql.jdbc.Statement, java.lang.String, java.lang.String, com.mysql.jdbc.Buffer, int, com.mysql.jdbc.Connection, int, int, boolean, java.lang.String, boolean) @bci=208, line=1665 (Compiled frame)
 - com.mysql.jdbc.Connection.execSQL(com.mysql.jdbc.Statement, java.lang.String, int, com.mysql.jdbc.Buffer, int, int, boolean, java.lang.String, boolean, boolean) @bci=255, line=3170 (Compiled frame)
 - com.mysql.jdbc.Connection.execSQL(com.mysql.jdbc.Statement, java.lang.String, int, com.mysql.jdbc.Buffer, int, int, boolean, java.lang.String, boolean) @bci=17, line=3099 (Compiled frame)

Any other thread that wants to access the database after that, gets locked at 
- com.mysql.jdbc.Statement.executeQuery(java.lang.String) @bci=15, line=1058 (Compiled frame)

Please tell me if you need any other information.

How to repeat:
It's pretty hard, because it happens randomly.  

Suggested fix:
None.
[14 Dec 2006 16:58] Patrick Casey
Another stack of the same symptom:

        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:113)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:160)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:188)
        - locked <0x9231a108> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:1931)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2380)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2909)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1600)
        at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1125)
        - locked <0x922c9b10> (a java.lang.Object)
        at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:677)
        at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:794)
        - locked <0x922c9b10> (a java.lang.Object)
        at sun.reflect.GeneratedMethodAccessor78.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:324)
        at com.glide.db.PreparedStatementWrapper.invoke(PreparedStatementWrapper.java:43)
        at $Proxy3.execute(Unknown Source)
        at com.glide.db.DBLazyWriter.process(DBLazyWriter.java:270)
        at com.glide.db.DBLazyWriter.run(DBLazyWriter.java:51)
[15 Dec 2006 9:58] Tonci Grgin
Hi to all.
It is virtually impossible to tell what happened just by looking into stack trace provided... Java itself is not very keen on multithreading. Things may be threadsafe, but not necessarily shareable across threads due to JDBC API interactions that can cause non-obvious behavior and/or deadlock scenarios to occur since the API is not designed to be used from multiple threads at once.

Can any of you post small but complete test case which reproduces this error? Please check your firewall SW if used.
[16 Jan 2007 0:00] Bugs System
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".
[29 Apr 2011 12:53] Walt Corey
I am seeing similar behavior. Also in profiling a program that runs very slowly I see the #1 hotspot is com.mysql.jdbc.util.ReadAheadInputStream.fill(int), where in 29000 invocations elapsed time in this method is over 76 seconds.

I disagree with your assertion about Java and multithreading. There is this little thing called thread local storage to separate variables if there is no other means. I reject that excuse as it implies straight JBDC can not be multi-threaded. But, more back to this existing bug report. I see via inspection with jconsole threads blocked with block count = thousands in one thread while other threads have blocked count of 4 or 5. It seems clearly one thread is being favored over the others.

My Environment is Ubuntu 10.4 with MySQL Connector 5.1.13. If there is any other information you'd need please let me know.
[29 Apr 2011 13:36] Mark Matthews
Walt,

The issue is that there are things in the JDBC API that don't make it *natural* to use from multiple threads, i.e. concurrent interactions on statements that can cause things to happen to already open result sets, for example. 

As to whether a thread is being "favored" or not, the JDBC driver itself is not starting any threads in the cases listed here, nor coordinating between any other instances of connections The blocking is because of the very fact that the JDBC api *is* blocking, and it appears that the other commenters expect to be able to share a connection between threads and have multiple simultaneously processing statements. That's just not possible. 

As to what *you* observe, understand there's more than one system at play here. Threads being blocked or not in the JVM are because they are blocked at the other end, i.e. mysqld, by locks and mutexes there. It is not uncommon to see threads waiting to read from the database in any normal JDBC application stack trace. If however one sees a particular thread stuck for some time, they should investigate what it is (usually) blocked on in the database, some row lock, some concurrency barrier, etc.
[29 Apr 2011 13:38] Mark Matthews
I'm putting this into "Needs Feedback", as from the outside it appears things are working as intended. However, if you can provide an example of where your application is blocked/deadlocked along with "show processlist" and "show engine innodb status" output to help determine whether this is a database-level block/deadlock or not, we'll re-open this.
[29 Apr 2011 14:17] Walt Corey
Thanks for your quick feedback Mark. Actually I was looking more for why the fill method would be taking 76% of the cpu in this application, as reported by NetBeans 9.1 profiler.  Here is the stack trace from jconsole.

tack trace: 
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:146)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@26920f13
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
   - locked java.lang.Object@3f1bbc2d
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2275)

What I saw, by way of strange 'blocking is in the jconsole thread page as well with total blocked and total waited
thread  Total Blocked    total Waited
1           2000            5
2             4             2

In this particular case there are 6 logical databases (Innodb) and 1 thread dedicated to each ldb. Here is the query in status
---TRANSACTION 0 1659091678, ACTIVE 11 sec, process no 5642, OS thread id 1242761536 fetching rows, thread declared inside InnoDB 499
mysql tables in use 2, locked 0
MySQL thread id 55709, query id 875301368 usmaydwkjmlmdf1.na.global.ad 10.51.18.60 trovix Sending data
select upddocumen0_.UpdDocumentUpdateLog_UpdateId as col_0_0_, upddocumen0_.UpdDocumentUpdateLog_DocId as col_1_0_ from upddocumentupdatelog upddocumen0_, upddocument upddocumen1_ where upddocumen0_.UpdDocumentUpdateLog_DocId=upddocumen1_.UpdDocument_DocId and upddocumen0_.UpdDocumentUpdateLog_BatchNum>0 and upddocumen1_.UpdDocument_DocState=400 and upddocumen0_.UpdDocumentUpdateLog_Action='I' and upddocumen0_.UpdDocumentUpdateLog_UpdateId>1143811310 limit 1000
Trx read view will not see trx with id >= 0 1659091679, sees < 0 1659091125

In this case, at this point 4 of the 6 threads have finished and what I depicted above shows similar to what I originally saw where 5 of the 6 threads would have total blocked around 5 and total wait around 3 and 1 of the threads would have total blocked around 28,000 and some corresponding wait value statistically higher than the other threads. 

For my purposes the cpu time was low, which I expect as the bulk of the time should rightfully be reading the table (all threads are executing the same code on the same table, just in a different logical db. I got them impression only one of the threads...which is to say only one connection was being allowed to run while the others were blocked waiting for it to 'finish'. 

Here is a code fragment of the query (it's in JPA the dialect is Innodb.

queryDocIds = eventsEM.createQuery("SELECT u.updDocumentUpdateLogUpdateId, u.updDocumentUpdateLogDocId FROM Upddocumentupdatelog u, Upddocument d WHERE u.updDocumentUpdateLogDocId = d.updDocumentDocId and u.updDocumentUpdateLogBatchNum > 0 and d.updDocumentDocState = 400 and u.updDocumentUpdateLogAction = :action and u.updDocumentUpdateLogUpdateId > :updid");

The limit is set to 10,000. I thought the 76% time in the fill method and the subsequent hit on a google search where there was a 'blocking' issue I could shed some further light by way of the strange total blocked and total wait distrubution across threads executing the same code. Here is the invoking code:

    private void getDocIds() {
        /*
         * get the current documents
         */
        Set<Event> eventSet = new TreeSet<Event>();
        Set<EventBase> eventSetPrime = new HashSet<EventBase>();
        Query maxLog = eventsEM.createQuery("select max(l.updDocumentUpdateLogUpdateId) from Upddocumentupdatelog l");
        maxLog.setHint("org.hibernate.readOnly", true);
        Long maxUpdateId = (Long)maxLog.getSingleResult();
        Long currentUpdId = 0L;
        
        do {
            queryDocIds.setParameter("updid", currentUpdId);
            List<Object[]> tmp =  (List<Object[]>) queryDocIds.getResultList();
            for (Object log[] : tmp) {
                if (log[0] instanceof Long) {
                    currentUpdId = ((Long)log[0]).longValue();
                } else if (log[0] instanceof Integer) {
                    currentUpdId = (long)((Integer)log[0]).intValue();
                }
                mockDocs.add(((Long)log[1]).intValue());
            }
            eventsEM.clear();
            
        } while (currentUpdId < maxUpdateId);

In the show status that task was captured after running 11 seconds, I've seen it go to 15-16 and it started at 2-5 in the front of the file. Indexes exist on predicate columns. Of the 6 logical db's owning the same schema they are split between 2 servers. While I am curious why such a high % of time is in fill(), I thought the jconsole output would be pertinent to this original thread as I also sensed only one thread was being favored. 

Anything else you might need, please let me know.

Walt
[29 Apr 2011 14:26] Mark Matthews
Walt,

Are you sure your profiler is measuing cpu ticks and not wall clock time? Most profilers I've run into (but I haven't used NB's), measure wall-clock time by default, because it's much cheaper and thus less invasive to do that instrumentation. If what is being reported is wall-clock time, then the amount of time there makes sense.

One other question, what platform is your application running on? We've seen *vastly* different behavior on how quickly I/O buffers get filled between Solaris and Linux (and thus the number of calls to ReadAheadInputStream.fill(), because it reads what's available, it doesn't block unless it needs to read more than what's available).
[29 Apr 2011 15:10] Walt Corey
Hi Mark,
  Ubuntu 10.4 with MySQL Connector 5.1.13.

I stand corrected on the other, the column just says Self Time as a %. I think this is confusing design in the profiler as what is getting measured does not take into account the program is largely waiting (for the read to complete) so it is somewhat misleading as say a program spent 99% of the time waiting for IO and 1% of the time executing instructions, saying

    Method           Self Time %   Self Time       Invocations
com.mysql.blahblah   76%             200000ms           29

may be is misleading but on the left is the little red progress bar and where that bar is for fill() is perhaps 76% of the field. The next in descending order is barely showing red at all. 

The think of it is mark, if I do an explain on the query it shows:

mysql> explain select upddocumen0_.UpdDocumentUpdateLog_UpdateId as col_0_0_, upddocumen0_.UpdDocumentUpdateLog_DocId as col_1_0_ from upddocumentupdatelog upddocumen0_, upddocument upddocumen1_ where upddocumen0_.UpdDocumentUpdateLog_DocId=upddocumen1_.UpdDocument_DocId and upddocumen0_.UpdDocumentUpdateLog_BatchNum>0 and upddocumen1_.UpdDocument_DocState=400 and upddocumen0_.UpdDocumentUpdateLog_Action='I' and upddocumen0_.UpdDocumentUpdateLog_UpdateId>1085407447 limit 10000;
+----+-------------+--------------+--------+-------------------------------------------------------------------------------------------------------+--------------------------------+---------+--------------------------------------------------+---------+-------------+
| id | select_type | table        | type   | possible_keys                                                                                         | key                            | key_len | ref                                              | rows    | Extra       |
+----+-------------+--------------+--------+-------------------------------------------------------------------------------------------------------+--------------------------------+---------+--------------------------------------------------+---------+-------------+
|  1 | SIMPLE      | upddocumen0_ | ref    | PRIMARY,UpdDocumentUpdateLog_ActionIdx,UpdDocumentUpdateLog_DocIdIdx,UpdDocumentUpdateLog_BatchNumIdx | UpdDocumentUpdateLog_ActionIdx | 3       | const                                            | 6056892 | Using where |
|  1 | SIMPLE      | upddocumen1_ | eq_ref | PRIMARY,UpdDocument_DocIdIdx,upddocument_docstateidx                                                  | PRIMARY                        | 4       | tresumes.upddocumen0_.UpdDocumentUpdateLog_DocId |       1 | Using where |
+----+-------------+--------------+--------+-------------------------------------------------------------------------------------------------------+--------------------------------+---------+--------------------------------------------------+---------+-------------+
2 rows in set (0.00 sec)

This program I've left running for days, if it merely needs to read 6million rows that shouldn't take days. Granted, the file is busy but I've tried to specify readonly, not sure if that isn't a nop for mysql, and the table uses mvcc so I can't see any contention issues.  I've changed the queries to exclude any hidden hibernate session cache mgmt issues. This, according to Hibernate should be about bare metal (native jdbc) speed. The profile hot spot page seems to confirm that.

I can continue digging on this end if that is helpful.

Thanks for your time on this too!

Walt
[29 Apr 2011 15:18] Walt Corey
Also, this is running on a quad core zeon processor, Dell Precision 490.
[29 Apr 2011 15:38] Walt Corey
The other thing very curious about this is the 2 remaining logical databases actually coexist under the same physical db (the same server) and from jconsole both threads show blocked on 

Stack trace: 
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:146)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@71e069be

Yet under show innodb status\G, I only see one task executing. 

I am not sure how to interpret that, further in the status output is:
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
2 read views open inside InnoDB
Main thread process no. 5642, id 1198565696, state: sleeping
Number of rows inserted 311256969, updated 29760857, deleted 50630403, read 841380722957
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 473238.76 reads/s
[29 Apr 2011 16:12] Walt Corey
Here is an example of what I was referring to re: one thread getting preference, or rather one connection.

Name: pool 1 thread 1
State: RUNNABLE
Total blocked: 457  Total waited: 10

Stack trace: 
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:146)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@121c4be
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
   - locked java.lang.Object@4ffb9686
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2275)
   - locked java.lang.Object@4ffb9686

Note the total blocked count. 

Here is the other thread:
Name: pool 1 thread 2
State: RUNNABLE
Total blocked: 14  Total waited: 3

Stack trace: 
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:146)
com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
   - locked com.mysql.jdbc.util.ReadAheadInputStream@71e069be
com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2499)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2941)
com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3489)
com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1959)
com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2113)
com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2568)
   - locked java.lang.Object@443e735a
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2113)
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2275)
   - locked java.lang.Object@443e735a

This invocation has been running for 96 minutes.
[5 Dec 2011 21:37] Stanimir Simeonoff
I have rarely the same issue, the culprit was listed as a sleeping process in mysql: SHOW PROCESSLIST. 
Killing the process (connection) resumes the normal operation.

Also, fill used to have a bug when read(byte[]) returns 0, leading to infinite loop, dunno it has been fixed.
[5 Dec 2011 23:09] Mark Matthews
@Stanimir

I don't seem to remember running into that bug being filed. Do you have any more information? I see that fill() is checking for <= 0 pretty much everywhere, but it has been since the day it was written. If you've got more details, we'd love to look into the issue further.
[6 Dec 2011 9:07] Stanimir Simeonoff
@Mark 

While it is checked everywhere indeed it never throws any exception when used by 'MysqlIO.skipFully()', skip() shall not return -1 (or negative) but it's free to throw an exception according to InputStream spec. skipFully() loops till it either get performance the task or gets a negative return value, that never happens.

I changed our version of ReadAheadInputStream to just throw EOF when underlyingStream.reads return -1 and also checking Thread.interrupted() to throw InterruptedIOException. Bailing out always seemed like correct behavior.

(small disclaimer) My memory is a bit vague though, and I did the change not recently but I believe that was the culprit.
---

To the current bug, I spent few hours during the night examining the code: I can't be sure but MysqlIO.clearInputStream() depends on the available data in the (socket) buffer. The data might be still in transit and available() would return zero, so there could be stale data unread.
[7 Mar 2014 16:15] Stanimir Simeonoff
The core of the problem is MysqlIO.clearInputStreams - the method has a very naive implementation. It attempts to clear up the data currently available in the socket buffer (SocketInputStream.available()) which could be either too small or just empty and that data could be still in transit.

Failure to clear the data would result into bogus header. The method should never exist in its form - i.e. attempting to clear up the steams based on the data locally available. Morealso available() is not necessary to be implemented and may return always zero as a valid result.
[12 Jun 2014 3:04] Davi Arnaut
Linux kernels version 3.6 and earlier (including 2.6.32) have a bug [1] which makes requests for the amount of available bytes to read in a socket in CLOSE_WAIT state to return 1 even after the EOF has been read.

This bug makes SocketInputStream.available return 1 for sockets in CLOSE_WAIT state and causes a seemly infinite loop in MysqlIO.clearInputStream where it attempts to read from the socket until the number of available bytes reaches 0, but there is nothing to read.

1. https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=a3374c4

Java strack trace of a thread looping in clearInputStream:

   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAvailable(Native Method)
        at java.net.PlainSocketImpl.available(PlainSocketImpl.java:472)
        - locked <0x00007f674094a498> (a java.net.SocksSocketImpl)
        at java.net.SocketInputStream.available(SocketInputStream.java:217)
        at com.mysql.jdbc.util.ReadAheadInputStream.available(ReadAheadInputStream.java:232)
        at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:961)
        at com.mysql.jdbc.ServerPreparedStatement.serverPrepare(ServerPreparedStatement.java:1690)
        - locked <0x00007f672c938970> (a java.lang.Object)
        at com.mysql.jdbc.ServerPreparedStatement.<init>(ServerPreparedStatement.java:427)
        at com.mysql.jdbc.JDBC4ServerPreparedStatement.<init>(JDBC4ServerPreparedStatement.java:44)
        [reset omitted]

Sample trace of the systems calls in the above thread:

        ioctl(405, FIONREAD, [1])               = 0
        ioctl(405, FIONREAD, [1])               = 0
        ioctl(405, FIONREAD, [1])               = 0
        ioctl(405, FIONREAD, [1])               = 0
        ioctl(405, FIONREAD, [1])               = 0
        ioctl(405, FIONREAD, [1])               = 0
[17 Jun 2014 0:13] Filipe Silva
Hi Davi,

Thanks for your feedback. It would be nice to have some more detail on this. Full stack traces and perhaps some profiling info, if possible.

Have you tried to include the changes you suggest in your own Connector/J build?
[17 Jun 2014 17:55] Davi Arnaut
The stacktrace down to application specific code:

   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAvailable(Native Method)
        at java.net.PlainSocketImpl.available(PlainSocketImpl.java:472)
        - locked <0x00007f674094a498> (a java.net.SocksSocketImpl)
        at java.net.SocketInputStream.available(SocketInputStream.java:217)
        at com.mysql.jdbc.util.ReadAheadInputStream.available(ReadAheadInputStream.java:232)
        at com.mysql.jdbc.MysqlIO.clearInputStream(MysqlIO.java:961)
        at com.mysql.jdbc.ServerPreparedStatement.serverPrepare(ServerPreparedStatement.java:1690)
        - locked <0x00007f672c938970> (a java.lang.Object)
        at com.mysql.jdbc.ServerPreparedStatement.<init>(ServerPreparedStatement.java:427)
        at com.mysql.jdbc.JDBC4ServerPreparedStatement.<init>(JDBC4ServerPreparedStatement.java:44)
        at sun.reflect.GeneratedConstructorAccessor52.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.ServerPreparedStatement.getInstance(ServerPreparedStatement.java:355)
        at com.mysql.jdbc.ConnectionImpl.serverPrepareStatement(ConnectionImpl.java:4880)
        [application specific trace omitted]

What kind of profiling info do you need?

> Have you tried to include the changes you suggest in your own Connector/J build?

We simply removed the clearInputStream function.
[18 Jun 2014 11:25] Alexander Soklakov
Hi Davi,

Thank you for such interesting finding!

According to kernel bug fix, the problem occurs when application consumed all bytes from socket. That means on Java side the InputBuffer is in EOF state and can't be reused.

We have a bug with consulting InputStream.available() at this stage, there shouldn't be any value of such attempt, the method should be refactored.

As for your stack trace, it seems the only possible reason is that your code tries to reuse connection when it is in closing state, maybe by the other side.

BTW, do you think this problem is related to initial one reported here?
[18 Jun 2014 17:41] Davi Arnaut
> As for your stack trace, it seems the only possible reason is that your code tries to reuse connection when it is in closing state, maybe by the other side.

Yes, like, connection timeout or connection killing, where the server closes its side of the connection.

> BTW, do you think this problem is related to initial one reported here?

Not sure. Based on the other comments, seemed to be the closest one that was still open.
[19 Jun 2014 14:44] Filipe Silva
There is no proof that the issue reported by Davi Arnaut on Jun 12 is related to the initial report, so this part was moved to the bug report Bug#73053 and will be pursued there.

This report will remain open until more feedback or util the confirmation that these two issues are related.

Thank you,
[4 Dec 2014 18:08] Filipe Silva
The original reported bug has all the symptoms of the bug reported in Bug#74739.

The failure occurs due to a combination of settings for query cache usage while fetching cursors for prepared statements. The bug is actually observed in the server and can be tracked in Bug#74979.

Please reopen of file a new bug if you have additional information that contradicts this.

Thank you.
[8 Dec 2014 7:30] Alexander Soklakov
Marked as duplicate of Bug#74739