| Bug #53357 | connection pooling not closed reader on error | ||
|---|---|---|---|
| Submitted: | 2 May 2010 13:30 | Modified: | 28 Jun 2010 13:40 |
| Reporter: | Moshe Lampert | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | Connector / NET | Severity: | S2 (Serious) |
| Version: | 6.2.3, 6.3.x | OS: | Any |
| Assigned to: | Vladislav Vaintroub | CPU Architecture: | Any |
[2 May 2010 13:30]
Moshe Lampert
[3 May 2010 10:49]
Tonci Grgin
Hi Moshe and thanks for your report. "TimeoutException in MySql.Data.MySqlClient.TimedStream.StopTimer" was introduced specifically cause we did not wanted to close the socket. So datareader in such cases might indeed still be open. So only thing I see here is to make sure the reader is closed, by putting "using" or something similar. However, this is not absolutely clear to me so if you don't like the answer please attach full test case so I can look into it more.
[3 May 2010 10:50]
Tonci Grgin
Note to myself: Bug#53097
[3 May 2010 13:24]
Moshe Lampert
I think that when connection is closed and returned to the pool, regardless of reader status, It must be closed. This error message is useless on the next use of this connection. Using is not useful because reader can't have "Dispose" function.
[5 May 2010 5:32]
Tonci Grgin
Moshe, as I said, it is not absolutely clear to me... Can you please attach a test case so I can check what's happening and pass this to Reggie.
[5 May 2010 5:56]
Moshe Lampert
Test case: console application, vb.net 2010, MySQL.Data 6.2.2.0 from GAC
Sub Main()
Dim Conn As New MySql.Data.MySqlClient.MySqlConnection("server=localhost;user id=; password=; database=; pooling=true; Connect Timeout=3;default command timeout=1;Connection reset =false")
Using Conn
Conn.Open()
Dim Cmd As MySqlCommand = Conn.CreateCommand()
Try
Cmd.CommandText = "select * from very_large_table"
Dim oReader = Cmd.ExecuteReader()
While oReader.Read
' do nothing
End While : oReader.Close()
Catch ex As Exception
Console.Write(ex.Message)
'^^ Timeout expired. The timeout period elapsed prior
'to completion of the operation or the server is not responding.
End Try
End Using
Using Conn
Conn.Open()
Dim Cmd As MySqlCommand = Conn.CreateCommand()
Cmd.CommandText = "select * from very_large_table limit 1" ' the exception
Dim oReader = Cmd.ExecuteReader()
' ^^ There is already an open DataReader associated with this
'Connection which must be closed first.
While oReader.Read
' do nothing
End While
End Using
End Sub
[5 May 2010 12:15]
Tonci Grgin
Moshe, just a note on "Using is not useful because reader can't have "Dispose" function." I do not get it. DataReader *is* IDisposable and something like dr.Dispose(); is perfectly ok...
[13 May 2010 13:37]
Tonci Grgin
Moshe, I can't repeat this... In general query log I see 5 times 5 connections allocated (Min pool size is 5) and I'm reading ~90000 records... Output: mysql Information: 1 : 1: Connection Opened: connection string = 'server=opensol;database=solusd;User Id=root;password=tonchika;port=3306;logging=True;pooling=True;Minimum Pool Size=5;Maximum Pool Size=30;Connect Timeout=5;Default Command Timeout=2;Connection Reset=False' mysql Information: 1 : 2: Connection Opened: connection string = 'server=opensol;database=solusd;User Id=root;password=tonchika;port=3306;logging=True;pooling=True;Minimum Pool Size=5;Maximum Pool Size=30;Connect Timeout=5;Default Command Timeout=2;Connection Reset=False' mysql Information: 1 : 3: Connection Opened: connection string = 'server=opensol;database=solusd;User Id=root;password=tonchika;port=3306;logging=True;pooling=True;Minimum Pool Size=5;Maximum Pool Size=30;Connect Timeout=5;Default Command Timeout=2;Connection Reset=False' mysql Information: 1 : 4: Connection Opened: connection string = 'server=opensol;database=solusd;User Id=root;password=tonchika;port=3306;logging=True;pooling=True;Minimum Pool Size=5;Maximum Pool Size=30;Connect Timeout=5;Default Command Timeout=2;Connection Reset=False' mysql Information: 1 : 5: Connection Opened: connection string = 'server=opensol;database=solusd;User Id=root;password=tonchika;port=3306;logging=True;pooling=True;Minimum Pool Size=5;Maximum Pool Size=30;Connect Timeout=5;Default Command Timeout=2;Connection Reset=False' mysql Information: 3 : 1: Query Opened: SHOW VARIABLES mysql Information: 4 : 1: Resultset Opened: field(s) = 2, affected rows = -1, inserted id = -1 mysql Information: 5 : 1: Resultset Closed. Total rows=268, skipped rows=0, size (bytes)=6338 mysql Information: 6 : 1: Query Closed mysql Information: 3 : 1: Query Opened: SHOW COLLATION mysql Information: 4 : 1: Resultset Opened: field(s) = 6, affected rows = -1, inserted id = -1 mysql Information: 5 : 1: Resultset Closed. Total rows=127, skipped rows=0, size (bytes)=3958 mysql Information: 6 : 1: Query Closed mysql Information: 3 : 1: Query Opened: SET NAMES utf8 mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0 mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0 mysql Information: 6 : 1: Query Closed mysql Information: 3 : 1: Query Opened: SET character_set_results=NULL mysql Information: 4 : 1: Resultset Opened: field(s) = 0, affected rows = 0, inserted id = 0 mysql Information: 5 : 1: Resultset Closed. Total rows=0, skipped rows=0, size (bytes)=0 mysql Information: 6 : 1: Query Closed mysql Information: 10 : 1: Set Database: solusd mysql Information: 3 : 1: Query Opened: SELECT * FROM dobra mysql Information: 4 : 1: Resultset Opened: field(s) = 17, affected rows = -1, inserted id = -1 0-2402 H 0-2403 0-303 0-3603 ..... HAN-12414 SHF200-02 HThe thread 0xa18 has exited with code 0 (0x0). AN-12564 SHF200-04 ..... HC 3338 HC 9996 GRXS040M CSR030B CSR030T Total rows read: 89847 mysql Information: 5 : 1: Resultset Closed. Total rows=89847, skipped rows=0, size (bytes)=8148523 mysql Information: 6 : 1: Query Closed Done.
[13 May 2010 13:39]
Tonci Grgin
Test case used:
using (MySqlConnection conn = new MySqlConnection("DataSource=**;Database=**;UserID=root;Password=**;PORT=**;logging=true;pooling=true; Min Pool Size=5; Max Pool Size=30; Connect Timeout=5; default command timeout=1;Connection reset =false"))
{
conn.Open();
MySqlCommand cmdCreateTable = new MySqlCommand("SELECT * FROM my_big_table", conn);
using (MySqlDataReader oReader = cmdCreateTable.ExecuteReader())
{
int rowsRead = 0;
while (oReader.Read())
{
//Console.WriteLine(oReader["Artikl"]);
rowsRead++;
}
Console.WriteLine("Total rows read: " + rowsRead.ToString());
}
}
Console.WriteLine("Done.");
[13 May 2010 13:40]
Tonci Grgin
Not a small table: mysql Information: 4 : 1: Resultset Opened: field(s) = 17, affected rows = -1, inserted id = -1 Total rows read: 89847 mysql Information: 5 : 1: Resultset Closed. Total rows=89847, skipped rows=0, size (bytes)=8148523 mysql Information: 6 : 1: Query Closed Done.
[13 May 2010 13:46]
Moshe Lampert
Do you get an IO operation exception on the first query? If the first query works, the second will works well.
[13 May 2010 13:49]
Tonci Grgin
Moshe, I tested with just one query and there was no exception...
[13 May 2010 15:31]
Moshe Lampert
If your server is fast there are no problem. the problem is when server is under heavy load. You can try "select sleep(10);", with command timeout of 4 seconds.
[14 May 2010 5:44]
Tonci Grgin
Sure Moshe, I thought of that too.
[14 May 2010 6:07]
Tonci Grgin
Moshe, all seems fine... Instead of sleep (makes no sense to open reader on sleep) I made new index-less table with "Total rows=1078164, skipped rows=0, size (bytes)=97782276" from the former table used in test. Test started:14.05.10 8:00:23 mysql Information: 3 : 1: Query Opened: SELECT * FROM ** mysql Information: 4 : 1: Resultset Opened: field(s) = 17, affected rows = -1, inserted id = -1 Total rows read: 1078164 mysql Information: 5 : 1: Resultset Closed. Total rows=1078164, skipped rows=0, size (bytes)=97782276 mysql Information: 6 : 1: Query Closed Test ended in 00:00:13.2294921 Done. mysql Information: 2 : 1: Connection Closed mysql Information: 2 : 5: Connection Closed mysql Information: 2 : 3: Connection Closed mysql Information: 2 : 2: Connection Closed mysql Information: 2 : 4: Connection Closed The thread 0xbb4 has exited with code 0 (0x0). The thread 0x17e4 has exited with code 0 (0x0). As you can see, test ended in 13.2294921 seconds which is far more than 1s allowed. I also set the command timeout explicitly on MySQLCommand object. I'm beginning to think there might be something wrong in your environment.
[14 May 2010 6:37]
Moshe Lampert
I re-check my testcase on local server, and see this result: "select * from large_table" ... works (starting fetch in a half-second), but "select * from large_table group by large_unindexed_field order by order otherunindexed_filed", or run simple "select" while table locked by large "select"/"update" in other process, cause the exception. The I/O timeout exception is relevant for only the executing (and locked) time, and not sending time, that is the 13-sec wait of your example.
[14 May 2010 6:41]
Tonci Grgin
You are right again, retesting.
[14 May 2010 7:07]
Tonci Grgin
Wow, Moshe, I need a moment or two to analyze the results...
Problem seems to be in command.cs, line 318:
internal void Close(MySqlDataReader reader)
{
if (statement != null)
statement.Close(reader);
ResetSqlSelectLimit();
connection.driver.CloseQuery(connection, statement.StatementId);
ClearCommandTimer();
}
Where "statement" is NULL thus connection.driver.CloseQuery(connection, statement.StatementId); bombs out.
[14 May 2010 7:56]
Tonci Grgin
Verified as described. After a long running query is aborted, c/NET bombs out in command.cs, around line 318
internal void Close(MySqlDataReader reader)
{
if (statement != null)
statement.Close(reader);
ResetSqlSelectLimit();
connection.driver.CloseQuery(connection,
statement.StatementId);
ClearCommandTimer();
}
cause "statement" is NULL.
DML/DDL in ftp://ftp.mysql.com/pub/mysql/upload/bug53357.rar
Test case:
using (MySqlConnection conn = new MySqlConnection("DataSource=**;Database=bug53357;UserID=root;Password=**;PORT=3306;logging=true;pooling=true; Min Pool Size=5; Max Pool Size=30; Connect Timeout=5; default command timeout=1;Connection reset=false"))
{
conn.Open();
MySqlCommand cmdCreateTable = new MySqlCommand("SELECT * FROM testbug53357 ORDER BY Godina, Artikl", conn);
System.DateTime started = DateTime.Now;
Console.WriteLine("Test started:" + started.ToString());
try
{
using (MySqlDataReader oReader = cmdCreateTable.ExecuteReader())
{
System.DateTime ended1 = DateTime.Now;
TimeSpan diff1 = ended1 - started;
Console.WriteLine("Prep ended in " + diff1.ToString());
int rowsRead = 0;
while (oReader.Read())
{
rowsRead++;
}
Console.WriteLine("Total rows read: " + rowsRead.ToString());
}
}
catch (Exception ex)
{
Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + " " + "Exception: " + ex.Message);
}
System.DateTime ended = DateTime.Now;
TimeSpan diff = ended - started;
Console.WriteLine("Test ended in " + diff.ToString());
if (conn.State == ConnectionState.Closed)
{
conn.Open();
}
cmdCreateTable.CommandText = "SELECT 1+1";
try
{
using (MySqlDataReader oReader1 = cmdCreateTable.ExecuteReader())
{
int rowsRead = 0;
while (oReader1.Read())
{
rowsRead++;
}
Console.WriteLine("Total rows read2: " + rowsRead.ToString());
}
}
catch (Exception ex)
{
Console.Out.WriteLine(DateTime.UtcNow.ToLongTimeString() + " " + "Exception: " + ex.Message);
}
}
Console.WriteLine("Done.");
}
[14 May 2010 8:03]
Tonci Grgin
Retrying uploadof dml/dll to ftp://ftp.mysql.com/pub/mysql/upload/bug533571.rar Anyways, as Moshe said, it's enough to have big unindexed table to force the command timeout.
[10 Jun 2010 16:49]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/110740 812 Vladislav Vaintroub 2010-06-10 - When command is killed, e.g as result of timeout, error code returned from server is not necessarily 1317 (QueryInterrupted). It might as well be 1028 (FileSortAborted). Fix timeout handling to handle both error codes in the same fashion (bug #53357)
[10 Jun 2010 16:52]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/110741 813 Vladislav Vaintroub 2010-06-10 - When command is killed, e.g as result of timeout, error code returned from server is not necessarily 1317 (QueryInterrupted). It might as well be 1028 (FileSortAborted). Fix timeout handling to handle both error codes in the same fashion (bug #53357)
[10 Jun 2010 19:29]
Vladislav Vaintroub
pushed to 6.x series
[24 Jun 2010 10:00]
Vladislav Vaintroub
fixed in 6.0.7, 6.1.5, 6.2.4, and 6.3.3+
[28 Jun 2010 13:40]
Tony Bedford
An entry has been added to the 6.0.7, 6.1.5, 6.2.4, and 6.3.3 changelogs: After a timeout exception, if an attempt was made to reuse a connection returned to the connection pool the following exception was generated: [MySqlException (0x80004005): There is already an open DataReader associated with this Connection which must be closed first.] MySql.Data.MySqlClient.MySqlCommand.CheckState() +278 MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior) +43 MySql.Data.MySqlClient.MySqlCommand.ExecuteReader() +6 Controls.SimpleCommand.ExecuteReader(String SQL) in ...:323 Albums.GetImagesByAlbum(SimpleCommand Cmd, Int32 iAlbum, String Order, String Limit) in ...:13 Forecast.Page_Load(Object sender, EventArgs e) in ...:70 System.Web.UI.Control.OnLoad(EventArgs e) +99 System.Web.UI.Control.LoadRecursive() +50 System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +627
