MySQL Bugs: #85978: UPDATE Timeout then ExecuteReader returns null

Bug #85978	UPDATE Timeout then ExecuteReader returns null
Submitted:	18 Apr 2017 2:55	Modified:	10 Aug 2022 17:32
Reporter:	Matt Houser	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	Connector / NET	Severity:	S2 (Serious)
Version:	6.9.9	OS:	Windows
Assigned to:		CPU Architecture:	Any
Tags:	Timeout ExecuteReader

Description:
After many weeks of logging, etc., I have witnessed the following behaviour during periods of heavy UPDATEs:

1. UPDATE to table `A` times out. This is the exception stack:

MySql.Data.MySqlClient.MySqlException (0x80004005): Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.TimeoutException: Timeout in IO operation
   at MySql.Data.MySqlClient.TimedStream.StopTimer()
   at MySql.Data.MySqlClient.TimedStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.BufferedStream.Read(Byte[] array, Int32 offset, Int32 count)
   at MySql.Data.MySqlClient.MySqlStream.ReadFully(Stream stream, Byte[] buffer, Int32 offset, Int32 count)
   at MySql.Data.MySqlClient.MySqlStream.LoadPacket()
   at MySql.Data.MySqlClient.MySqlStream.ReadPacket()
   at MySql.Data.MySqlClient.NativeDriver.GetResult(Int32& affectedRow, Int64& insertedId)
   at MySql.Data.MySqlClient.Driver.GetResult(Int32 statementId, Int32& affectedRows, Int64& insertedId)
   at MySql.Data.MySqlClient.Driver.NextResult(Int32 statementId, Boolean force)
   at MySql.Data.MySqlClient.MySqlDataReader.NextResult()
   at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior)
   at MySql.Data.MySqlClient.ExceptionInterceptor.Throw(Exception exception)
   at MySql.Data.MySqlClient.MySqlConnection.Throw(Exception ex)
   at MySql.Data.MySqlClient.MySqlConnection.HandleTimeoutOrThreadAbort(Exception ex)
   at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior)
   at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader()

In my logging, timing from the previous log line to this is ~30 to ~40 seconds. So it seems to be timing out after ~30 seconds.

When the timeout happens, the row actually is updated anyways. So the timeout seems to be an "after update" timeout (ie. reading response).

These UPDATEs are always making this type of update:

  * Column A, DateTime, Indexed, changing non-NULL value to NULL. This column is changed non-NULL to non-NULL hundred/thousands of times before it's set to NULL (final value). All without issue.
  * Column B, DateTime, Indexed, changing NULL value to non-NULL (recording current timestamp).
  * Column C, Int32, Indexed, changing NULL value to non-NULL.

2. At the same time, or slightly milliseconds after, a command on table `B` will return "null" from "MySqlCommand.ExecuteReader()". The command could be an GET, INSERT, UPDATE, or DELETE.

Usually this happens on table `B`, but I have seen a few cases where it happened on table `A`.

In my logging, timing from the previous log line to this is < 1s. So ExecuteReader is executing for less than 1s before it returns null.

How to repeat:
I am unable to "force" this issue to occur. It is intermittent under (moderate to) heavy load.

I have not been able to reproduce this issue in staging/dev scenarios, only on a production system.

Additional Data
---------------

1. Usually, the issue presents itself across threads. The timeout happens in one thread, the ExecuteReader returning null is in another thread. However, this is not a hard-and-fast rule. I have witnessed 1 occurrence where it was the same thread:

 a) The timeout exception occurred on table `A`.
 b) The same command was repeated on table `A`, success this time.
 c) ExecuteReader returned null on the next command to table `B`.

2. The problem happens when there is increased load on the MySQL *server*.

 * When I have 3 workers running against the server, the problem does not occur.
 * When I have 6 workers running against the server, the problem occurs.

I all scenarios, there are 8 threads per worker connecting to the server.

3. The 2 issues always seem to happen in pairs: Timeout then ExecuteReader returns null.

4. The pairs are always together on the same worker computer.

5. In my source code, I am:

 * Never reusing a MySqlConnection object.
 * Using "using" where-ever possible (connections, commands, readers).

6. Slow Query Log is not reporting any slow queries at the times of these issues (long_query_time = 2).

Additional Notes
----------------

MySql Connector .NET Version: 6.9.9
MySql Server Version: 5.6.34 (Amazon RDS)

Hypothesis:

1. Connection times-out and is returned to the pool.
2. Connection is pulled from the pool, and is immediately in the "MySqlException.IsQueryAborted" state.

??

Hello  Matt Houser,

Thank you for the bug report.
I could not repeat the issue at our end using with Visual Studio 2013, Connector/NET 6.9.9 version.
Could you please provide repeatable test case (exact steps/sample project, screenshot etc. - please make it as private if you prefer) to confirm this issue at our end?

Thanks,
Chiranjeevi.

I have determined that the initial UPDATE times-out due to a slow query (45 seconds).

I have been trying to create a demo program, but I have not been able to yet.

However, I did create bug #86010 which seems related in that SLEEP appears to be "interrupted" after the timeout.

The reason I bring this up, is that (according to the MySql connector code in GitHub) ExecuteReader can return null if the query was interrupted. See MySqlException.IsQueryAborted

https://dev.mysql.com/doc/refman/5.7/en/error-messages-server.html#error_er_query_interrup...

OK. I can make it happen on demand now.

Step 1. Create this table:

CREATE TABLE `TestTable` (
  `Id` int(11) NOT NULL AUTO_INCREMENT,
  `Value` varchar(45) DEFAULT NULL,
  `Value2` int(11) DEFAULT NULL,
  PRIMARY KEY (`Id`)
) ENGINE=InnoDB;

Step 2. Put a breakpoint on line 28 and run the attached demonstration program.

Step 4. When your breakpoint is hit, run the following against your MySql database:

LOCK TABLES `TestTable` read;
SET @sl = SLEEP(45);
UNLOCK TABLES;

Step 5. While that is running, before it completes, continue the execution of the demonstration app. "ExecuteUpdateNoSleep" should block until the lock clears. A timeout exception should occur.

Step 6. Witness when ExecuteReader returns null in the subsequent attempt to UPDATE the record. But there's no reason this UPDATE should fail.

Demonstration Program

Attachment: Program.cs (text/plain), 5.27 KiB.

Hello  Matt Houser,

Thank you for the feedback and test case.
Verified this behavior on Visual Studio 2013 (C#.Net) and Connector/NET 6.9.9 version.

Thanks,
Chiranjeevi.

Screenshot

Attachment: 85978.JPG (image/jpeg, text), 252.71 KiB.

Hello Chiranjeevi,

Your screenshot is displaying the wrong exception.

Your screenshot is showing the timeout exception, which is expected to occur due to the table lock.

However, this bug is about the null value returned from ExecuteReader which occurs later in the demonstration program.

Please confirm.

This bug could not be reproduced and all the steps on "How to Repeat"
section, executed successfully.