MySQL Bugs: #74739: ReadAheadInputStream hangs on socket read

Bug #74739	ReadAheadInputStream hangs on socket read
Submitted:	7 Nov 2014 15:12	Modified:	28 Nov 2014 14:44
Reporter:	Yves Gillet	Email Updates:
Status:	Won't fix	Impact on me:	None
Category:	Connector / J	Severity:	S1 (Critical)
Version:	5.1.34	OS:	Any
Assigned to:	Filipe Silva	CPU Architecture:	Any

Description:
I reopen a new bug but it is linked to Bug #56411.
To summarize, the driver hangs on socket reading using the readaheadinputstream . Following stuck thread has this stacktrace:
java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:150)
        at java.net.SocketInputStream.read(SocketInputStream.java:121)
        at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100)
        at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143)
        at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173)
        - locked <0x000000078d418960> (a com.mysql.jdbc.util.ReadAheadInputStream)
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2911)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3337)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3327)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3814)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:870)
        at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1928)
        at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3268)
        at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:462)
        at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:2997)
        at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2245)
        at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:1373)
        - locked <0x000000078d4189b0> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:794)
        - locked <0x000000078d4189b0> (a com.mysql.jdbc.JDBC4Connection)
        at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2030)

 
I have also attached the logs as requested by last comment for #56411

How to repeat:
This seems to occur randomly on select * from table type of queries. Adding an order by clause prevented the problem.

driver trace logs

Attachment: readAheadHangs.log (application/octet-stream, text), 25.97 KiB.

Hi Yves,

Thank you for this bug report.

This problem is actually being observed for a long time, not only in Bug#56411 but also in Bug#24995 and others. So far we were unable to reproduce it. Lets try one more time.

Could you please describe your environment with more detail?
- Connection string used.
- Java version.
- Operating System (kernel version).
- Client and Server are in same machine?
- Single/multi-threaded application?
- Whatever you feel important mentioning.

Have you tried with other systems, configurations, different use cases?

Can you observe the same behavior in an isolated test case consulting the same data sources?

Thanks Yves for the detailed traces and stacks. They're very
helpful.

Looks like a server issue.

Response packet from the prepare (packet trace line 54/55):
    c.f. http://dev.mysql.com/doc/internals/en/com-stmt-prepare-response.html

    00 51 03 00 00 06 00 00     . Q . . . . . . 
    00 00 00 00                 . . . . 
    
    Statement ID = 51 03 00 00

Our execute packet (packet trace line 205/206):
    c.f. http://dev.mysql.com/doc/internals/en/com-stmt-execute.html
    
    [0b 00 00 00] 17 51 03 00     . . . . . Q . . 
     00 00 01 00  00 00 00        . . . . . . . 
    
    Statement ID = 51 03 00 00
    Flags = 00 (CURSOR_TYPE_NO_CURSOR)

EOF packet after the metadata (packet trace line 356):
    c.f. http://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html
    
    fe 00 00 61 00              . . . a . 
    
    Flags = 0x61 (bit flags includes SERVER_STATUS_CURSOR_EXISTS)

So we're not asking for a cursor, but actually getting one. We
don't expect a cursor so we try to read the result stream
immediately but it doesn't exist. I don't see 5.7 exhibiting this
behavior. I don't see any clarification in the docs of whether
this is "allowed" by the server.

Why are you using cursor fetch and server-prepared statements? I
believe Hibernate is setting TYPE_SCROLL_INSENSITIVE which
negates the request for a cursor. I didn't see this in the JDBC
log so I'm not if it's not being captured or not. If it wasn't
being set we should see a cursor requested in the execute packet.

Hi Jess,

thanks for your input, it helped me track down the problem !
It has to do with the parameter useCursorFetch=true and setting java.sql.Statement#setFetchSize the first time and not on the second time for the same query (under the same transaction).
I still don't know why in our code base this is happening, but this is definitely the problem. 
Interestingly, a server prepared statement is used even if I dont set the parameter. You will see the behavior in the small test provided.

Test case to cause the driver to hand with useCursorFetch

Attachment: MysqlJdbcTest.java (application/octet-stream, text), 1.92 KiB.

Update:
the problem still exists even if we use different transactions/connections. 
Once the server prepared statement has been created with cursor fetching the first time, all subsequent sessions/transactions will reuse it, event if no cursor fetch has been asked and therefore hangs the driver.

Hi Yves,

This is getting interesting. I seem to be unable to reproduce the error with your test case. I'm assuming that your code fails, exactly as is, while running against am MySQL Server 5.5.31. I've set up my environment with the same  server but it runs flawlessly. I may be missing something or you have some server configurations that are causing this behavior.

It would be very useful if you send us the settings you have in your server and the protocol trace for the test case we both are running. Could you do it please?

By the way, server prepared statements are being used in your code because this setting turned on automatically after you've set useCursorFetch=true. To be able to deal with cursors you also have to work with server prepared statements.

Thank you for your great feedback!

Hi Yves,

The behavior you described is related to query caching features in MySQL server, and it is a bug.

Meanwhile you have two options to avoid this problem: either disable query caching on server (by setting 'query_cache_size=0' or 'query_cache_type=OFF' [http://dev.mysql.com/doc/refman/5.5/en/query-cache.html]) or stop using cursor fetch in client (connection property 'useCursorFetch=false').

Thank you once again for this report and for your excellent feedback.

Hi Filipe

thanks for nailing it !
Unfortunately we have use cases where recovering big datasets makes the use of server cursors almost mandatory, and query cache helps performance wise, so we ll have to make a hard choice.
This bug seems to still exist even in the latest release version (tested with 5.6.21), can you link me a pointer on this server bug#  ?
Best regards
Yves.

Hi Yves,

Depending on if you have full access to queries that are being executed or not, you may overcome the problem by setting query_cache_type=DEMAND and using SQL_CACHE/SQL_NO_CACHE in your SELECT statements accordingly. Or keep query_cache_type=ON and add a unique comment in each query you know for sure that shouldn't be cached, for example.

Meanwhile I've confirmed that this can't be fixed on the Connector side in a clean way, so it has to be fixed in the server. It's reported as Bug#74979. You can track fix progress there from now on.

Please feel free to reopen this bug if there is something else you find regarding this issue in the connector side.

Many thanks for your collaboration.

Hi Filipe

thanks for the suggestions, we will dicuss our options now, while tracking the bug.
HTH,
Yves.

Bug#24995 was marked as duplicate of this one.