Debugging I / O limits
I am trying to figure out what IO is waiting for with google SQL cloud under upload. I am using plan D1, which should allow 100 concurrent requests. I don't see the statistics for concurrent requests in my dashboard, but locally I have a 64 thread pool, so I can never exceed 64 concurrent requests (2 more times from time to time). Also, my IO ops per second peak at 20.
Zooming in helps, but only slightly.
And the queries are pretty simple - pick 1, pick a small order at random.
All my 64 threads are stuck on google SQL IO in socketRead () like this:
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
- locked <5f74f841> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3049)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3503)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3492)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4043)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2809)
- locked <7856a45c> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2758)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:894)
- locked <7856a45c> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:732)
at org.jboss.jca.adapters.jdbc.CheckValidConnectionSQL.isValidConnection(CheckValidConnectionSQL.java:74)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.isValidConnection(BaseWrapperManagedConnectionFactory.java:1173)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.checkValid(BaseWrapperManagedConnection.java:461)
at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnectionFactory.getInvalidConnections(BaseWrapperManagedConnectionFactory.java:999)
at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.validateConnections(SemaphoreArrayListManagedConnectionPool.java:870)
at org.jboss.jca.core.connectionmanager.pool.validator.ConnectionValidator$ConnectionValidatorRunner.run(ConnectionValidator.java:277)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
Can you advise on how to understand the bottleneck?
EDIT: Also, this is the timeout exception that comes up eventually after getting stuck:
The last packet successfully received from the server was 13,969 milliseconds ago. The last packet sent successfully to the server was 13,969 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor107.newInstance(Unknown Source) [:1.6.0_45]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) [rt.jar:1.6.0_45]
at java.lang.reflect.Constructor.newInstance(Constructor.java:513) [rt.jar:1.6.0_45]
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1121)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3603)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3492)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4043)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2815)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2322)
at org.jboss.jca.adapters.jdbc.CachedPreparedStatement.executeQuery(CachedPreparedStatement.java:107)
at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:462)
at sun.reflect.GeneratedMethodAccessor77.invoke(Unknown Source) [:1.6.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [rt.jar:1.6.0_45]
at java.lang.reflect.Method.invoke(Method.java:597) [rt.jar:1.6.0_45]
at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementProxyHandler.java:122)
... 49 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3052)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3503)
... 62 more
EDIT2: The consumer is a Google Cloud Computing instance hosted with a DB.
source to share
Using filesort
indicates that the sort should be performed. If the amount of data is greater than sort_buffer_size
, then a temporary file will be created. Temporary files are slow in Cloud SQL, so avoiding them is paramount to get good performance /
The default for sort_buffer_size
is 2M. This is both a global and a session variable, so it could be a change in requests that require more memory.
mysql> SHOW VARIABLES LIKE 'sort_buffer_size';
+------------------+---------+
| Variable_name | Value |
+------------------+---------+
| sort_buffer_size | 2097152 |
+------------------+---------+
1 row in set (0.00 sec)
mysql>
Every time it is sort_buffer_size
too small, the state variable Created_tmp_files
will increase.
mysql> SHOW GLOBAL STATUS LIKE 'Created_tmp_files';
+-------------------+-------+
| Variable_name | Value |
+-------------------+-------+
| Created_tmp_files | 663 |
+-------------------+-------+
1 row in set (0.01 sec)
mysql>
More information Using filesort
can be found in Baron Schwartz's post on the MySQL Performance Blog . An in-depth discussion of "ORDER BY" can be found in Sergey Petrunias' blog post .
I wrote a small program ( mysql-sorttest ) to specifically test MySQL sorting performance.
In the default configuration (1000 lines), the data fits into memory ( Created_tmp_files
does not grow after the test), so queries are executed quickly:
$ ./sort -dsn="root:root@tcp(x.x.x.x:3306)/sorttest" prepare
2014/08/24 12:22:03 Start number of rows: 0
2014/08/24 12:22:06 End number of rows: 1000
$ ./sort -dsn="root:root@tcp(x.x.x.x:3306)/sorttest" run
2014/08/24 12:22:10 Sleep 10s
2014/08/24 12:22:10 Start oneRun
2014/08/24 12:22:20 Done 3000 requests
2014/08/24 12:22:20 Total requests: 300.00/s
$
For 5000 lines, the data does not fit into memory, and the speed drops significantly:
$ ./sort -dsn="root:root@tcp(x.x.x.x:3306)/sorttest" -table_size=5000 prepare
2014/08/24 12:22:53 Start number of rows: 1000
2014/08/24 12:23:08 End number of rows: 5000
$ ./sort -dsn="root:root@tcp(x.x.x.x:3306)/sorttest" run
2014/08/24 12:23:15 Sleep 10s
2014/08/24 12:23:15 Start oneRun
2014/08/24 12:23:25 Done 91 requests
2014/08/24 12:23:25 Total requests: 9.10/s
$
Commentary on ORDER BY RAND()
: As pointed out in numerous places , it is useful to avoid this type of query because it forces MySQL to randomly generate each row and then sort. This is CPU intensive, and with enough threads, it will eventually consume the entire CPU (or perhaps hit some other limits in mysqld).
source to share