From c9e6e045c2aa5a0a4d35cd6db772154a01aac6b4 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Wed, 10 Feb 2021 19:03:25 +0000 Subject: [PATCH 01/13] sync and async timer state rework --- .../Microsoft/Data/SqlClient/SNI/SNIPacket.cs | 2 +- .../Microsoft/Data/SqlClient/SqlBulkCopy.cs | 2 +- .../Microsoft/Data/SqlClient/SqlDataReader.cs | 2 +- .../src/Microsoft/Data/SqlClient/TdsParser.cs | 4 +- .../Data/SqlClient/TdsParserStateObject.cs | 98 ++++++++++++++++--- 5 files changed, 88 insertions(+), 20 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs index 857a300259..43debdb43c 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs @@ -75,7 +75,7 @@ public SNIPacket(SNIHandle owner,int id) { if (_data != null) { - Debug.Fail($@"finalizer called for unreleased SNIPacket, tag: {_traceTag}"); + //Debug.Fail($@"finalizer called for unreleased SNIPacket, tag: {_traceTag}"); } } diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs index b7939ece6b..b25e9dd9bc 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs @@ -2783,7 +2783,7 @@ private void CleanUpStateObject(bool isCancelRequested = true) { _stateObj.CancelRequest(); } - _stateObj._internalTimeout = false; + _stateObj.SetTimeoutStateStopped(); _stateObj.CloseSession(); _stateObj._bulkCopyOpperationInProgress = false; _stateObj._bulkCopyWriteTimeout = false; diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs index 8cb6e76f97..09d7826cdc 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SqlDataReader.cs @@ -956,7 +956,7 @@ private bool TryCloseInternal(bool closeReader) { _sharedState._dataReady = true; // set _sharedState._dataReady to not confuse CleanPartialRead } - _stateObj._internalTimeout = false; + _stateObj.SetTimeoutStateStopped(); if (_sharedState._dataReady) { cleanDataFailed = true; diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs index 9ce5c7a8d2..511ceb57c2 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParser.cs @@ -1896,7 +1896,7 @@ internal bool TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataRead // If there is data ready, but we didn't exit the loop, then something is wrong Debug.Assert(!dataReady, "dataReady not expected - did we forget to skip the row?"); - if (stateObj._internalTimeout) + if (stateObj.IsTimeoutStateExpired) { runBehavior = RunBehavior.Attention; } @@ -2520,7 +2520,7 @@ internal bool TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataRead stateObj._attentionSent = false; stateObj.HasReceivedAttention = false; - if (RunBehavior.Clean != (RunBehavior.Clean & runBehavior) && !stateObj._internalTimeout) + if (RunBehavior.Clean != (RunBehavior.Clean & runBehavior) && !stateObj.IsTimeoutStateExpired) { // Add attention error to collection - if not RunBehavior.Clean! stateObj.AddError(new SqlError(0, 0, TdsEnums.MIN_ERROR_CLASS, _server, SQLMessage.OperationCancelled(), "", 0)); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 5d36213755..b5138a1c2a 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -22,6 +22,11 @@ sealed internal class LastIOTimer internal abstract class TdsParserStateObject { + private const int TimeoutStopped = 0; + private const int TimeoutRunning = 1; + private const int TimeoutExpiredAsync = 2; + private const int TimeoutExpiredSync = 3; + private static int _objectTypeCount; // EventSource counter internal readonly int _objectID = Interlocked.Increment(ref _objectTypeCount); @@ -113,12 +118,12 @@ internal enum SnapshottedStateFlags : byte // Timeout variables private long _timeoutMilliseconds; private long _timeoutTime; // variable used for timeout computations, holds the value of the hi-res performance counter at which this request should expire + private int _timeoutState; // expected to be one of the constant values TimeoutStopped, TimeoutRunning, TimeoutExpiredAsync, TimeoutExpiredSync internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; - internal bool _internalTimeout; // an internal timeout occurred - - private readonly LastIOTimer _lastSuccessfulIOTimer; + private readonly LastIOTimer _lastSuccessfulIOTimer; + // secure password information to be stored // At maximum number of secure string that need to be stored is two; one for login password and the other for new change password private SecureString[] _securePasswords = new SecureString[2] { null, null }; @@ -760,7 +765,7 @@ private void ResetCancelAndProcessAttention() // operations. Parser.ProcessPendingAck(this); } - _internalTimeout = false; + SetTimeoutStateStopped(); } } @@ -1042,7 +1047,7 @@ internal bool TryProcessHeader() return false; } - if (_internalTimeout) + if (IsTimeoutStateExpired) { ThrowExceptionAndWarning(); return true; @@ -2247,11 +2252,54 @@ internal void OnConnectionClosed() } } - private void OnTimeout(object state) + public void SetTimeoutStateStopped() + { + _timeoutState = TimeoutStopped; + } + + public bool IsTimeoutStateExpired + { + get + { + int state = _timeoutState; + return state == TimeoutExpiredAsync || state == TimeoutExpiredSync; + } + } + + private void OnTimeoutAsync(object state) + { + //if (!_internalTimeout) + //{ + // _internalTimeout = true; + // // lock protects against Close and Cancel + + //} + Thread.Sleep(10000); + // we don't care about the return value here, we aren't going to make a choice using it we just + // need to set the state so that something else will pick it up + OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); + } + + private bool OnTimeoutSync() { - if (!_internalTimeout) + return OnTimeoutCore(TimeoutRunning, TimeoutExpiredSync); + } + + /// + /// attempts to change the timout state from the expected state to the target state and if it succeeds + /// will setup the the stateobject into the timeout expired state + /// + /// the state that is the expected current state, state will change only if this is correct + /// the state that will be changed to if the expected state is correct + /// boolean value indicating whether the call changed the timeout state + private bool OnTimeoutCore(int expectedState, int targetState) + { + Debug.Assert(targetState == TimeoutExpiredAsync || targetState == TimeoutExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); + + bool retval = false; + if (Interlocked.CompareExchange(ref _timeoutState, targetState, expectedState) == expectedState) { - _internalTimeout = true; + retval = true; // lock protects against Close and Cancel lock (this) { @@ -2349,6 +2397,7 @@ private void OnTimeout(object state) } } } + return retval; } internal void ReadSni(TaskCompletionSource completion) @@ -2386,7 +2435,7 @@ internal void ReadSni(TaskCompletionSource completion) if (_networkPacketTimeout == null) { _networkPacketTimeout = ADP.UnsafeCreateTimer( - new TimerCallback(OnTimeout), + new TimerCallback(OnTimeoutAsync), null, Timeout.Infinite, Timeout.Infinite); @@ -2396,6 +2445,8 @@ internal void ReadSni(TaskCompletionSource completion) // 0 == Already timed out (NOTE: To simulate the same behavior as sync we will only timeout on 0 if we receive an IO Pending from SNI) // >0 == Actual timeout remaining int msecsRemaining = GetTimeoutRemaining(); + int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + Debug.Assert(previousTimeoutState == TimeoutStopped, "previous timeout state was not Stopped"); if (msecsRemaining > 0) { ChangeNetworkPacketTimeout(msecsRemaining, Timeout.Infinite); @@ -2445,12 +2496,15 @@ internal void ReadSni(TaskCompletionSource completion) _networkPacketTaskSource.TrySetResult(null); } // Disable timeout timer on error + Interlocked.Exchange(ref _timeoutState, TimeoutStopped); ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); } else if (msecsRemaining == 0) - { // Got IO Pending, but we have no time left to wait - // Immediately schedule the timeout timer to fire - ChangeNetworkPacketTimeout(0, Timeout.Infinite); + { + // Got IO Pending, but we have no time left to wait + // disable the timer and set the error state by calling OnTimeoutSync + ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); + OnTimeoutSync(); } // DO NOT HANDLE PENDING READ HERE - which is TdsEnums.SNI_SUCCESS_IO_PENDING state. // That is handled by user who initiated async read, or by ReadNetworkPacket which is sync over async. @@ -2565,13 +2619,13 @@ private void ReadSniError(TdsParserStateObject stateObj, uint error) Debug.Assert(_syncOverAsync, "Should never reach here with async on!"); bool fail = false; - if (_internalTimeout) + if (IsTimeoutStateExpired) { // This is now our second timeout - time to give up. fail = true; } else { - stateObj._internalTimeout = true; + stateObj._timeoutState = TimeoutStopped; Debug.Assert(_parser.Connection != null, "SqlConnectionInternalTds handler can not be null at this point."); AddError(new SqlError(TdsEnums.TIMEOUT_EXPIRED, (byte)0x00, TdsEnums.MIN_ERROR_CLASS, _parser.Server, _parser.Connection.TimeoutErrorInternal.GetErrorMessage(), "", 0, TdsEnums.SNI_WAIT_TIMEOUT)); @@ -2794,6 +2848,20 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); + // the timer thread may be unreliable under high contention scenarios it cannot be + // assumed that the timeout has happened on the timer thread callback, check the timeout + // synchrnously and then call OnTimeoutSync to force an atomic change of state + if (TimeoutHasExpired) + { + OnTimeoutSync(); + } + + // try to change to the stopped state but only do so if currently in the running state + // and use cmpexch so that all changes out of the running state are atomic + int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + + ProcessSniPacket(packet, error); + ProcessSniPacket(packet, error); } catch (Exception e) @@ -3862,7 +3930,7 @@ internal void AssertStateIsClean() // Attention\Cancellation\Timeouts Debug.Assert(!HasReceivedAttention && !_attentionSent && !_attentionSending, $"StateObj is still dealing with attention: Sent: {_attentionSent}, Received: {HasReceivedAttention}, Sending: {_attentionSending}"); Debug.Assert(!_cancelled, "StateObj still has cancellation set"); - Debug.Assert(!_internalTimeout, "StateObj still has internal timeout set"); + Debug.Assert(_timeoutState == TimeoutStopped, "StateObj still has internal timeout set"); // Errors and Warnings Debug.Assert(!_hasErrorOrWarning, "StateObj still has stored errors or warnings"); } From 4ed4a32d95f0c296fb8da79fe57bbf50f197f180 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Wed, 10 Feb 2021 19:46:39 +0000 Subject: [PATCH 02/13] remove forced timeout wait --- .../netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index b5138a1c2a..b8aa19ccd5 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -2274,7 +2274,6 @@ private void OnTimeoutAsync(object state) // // lock protects against Close and Cancel //} - Thread.Sleep(10000); // we don't care about the return value here, we aren't going to make a choice using it we just // need to set the state so that something else will pick it up OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); From 9c57ae91b1a8c2590fa61203acc80b33b1e86106 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Thu, 11 Feb 2021 12:31:49 +0000 Subject: [PATCH 03/13] implement timeout state identity filtering --- .../Data/SqlClient/TdsParserStateObject.cs | 74 ++++++++++++++----- 1 file changed, 54 insertions(+), 20 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index b8aa19ccd5..4fedec53ac 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -119,6 +119,9 @@ internal enum SnapshottedStateFlags : byte private long _timeoutMilliseconds; private long _timeoutTime; // variable used for timeout computations, holds the value of the hi-res performance counter at which this request should expire private int _timeoutState; // expected to be one of the constant values TimeoutStopped, TimeoutRunning, TimeoutExpiredAsync, TimeoutExpiredSync + private int _timeoutIdentitySource; + private TimeoutState _spareTimeoutState; + private volatile int _timeoutIdentityValue; internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; @@ -2254,7 +2257,8 @@ internal void OnConnectionClosed() public void SetTimeoutStateStopped() { - _timeoutState = TimeoutStopped; + Interlocked.Exchange(ref _timeoutState, TimeoutStopped); + _timeoutIdentityValue = 0; } public bool IsTimeoutStateExpired @@ -2266,17 +2270,30 @@ public bool IsTimeoutStateExpired } } + private sealed class TimeoutState + { + public int IdentityValue { get; set; } + } + private void OnTimeoutAsync(object state) { - //if (!_internalTimeout) - //{ - // _internalTimeout = true; - // // lock protects against Close and Cancel - - //} - // we don't care about the return value here, we aren't going to make a choice using it we just - // need to set the state so that something else will pick it up - OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); +#if DEBUG + Thread.Sleep(13000); +#endif + int currentIdentityValue = _timeoutIdentityValue; + TimeoutState timeoutState = (TimeoutState)state; + if (timeoutState.IdentityValue == _timeoutIdentityValue) + { + // the return value is not useful here because no choice is going to be made using it + // we only want to make this call to set the state knowing that it will be seen later + OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); + } + else + { + Debug.WriteLine($"OnTimeoutAsync called with identity state={timeoutState.IdentityValue} but current identity is {currentIdentityValue} so it is being ignored"); + } + timeoutState.IdentityValue = 0; + Interlocked.CompareExchange(ref _spareTimeoutState, timeoutState, null); } private bool OnTimeoutSync() @@ -2431,20 +2448,32 @@ internal void ReadSni(TaskCompletionSource completion) { Debug.Assert(completion != null, "Async on but null asyncResult passed"); - if (_networkPacketTimeout == null) + // if the state is currently stopped then change it to running and allocate a new identity value from + // the identity source. The identity value is used to correlate timer callback events to the currently + // running timeout and prevents a late timer callback affecting a result it does not relate to + int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + if (previousTimeoutState == TimeoutStopped) { - _networkPacketTimeout = ADP.UnsafeCreateTimer( - new TimerCallback(OnTimeoutAsync), - null, - Timeout.Infinite, - Timeout.Infinite); + Debug.Assert(_timeoutIdentityValue == 0, "timer was previously stopped without resetting the _identityValue"); + _timeoutIdentityValue = Interlocked.Increment(ref _timeoutIdentitySource); } + _networkPacketTimeout?.Dispose(); + TimeoutState state = Interlocked.Exchange(ref _spareTimeoutState, null) ?? new TimeoutState(); + state.IdentityValue = _timeoutIdentityValue; + _networkPacketTimeout = ADP.UnsafeCreateTimer( + new TimerCallback(OnTimeoutAsync), + state, + Timeout.Infinite, + Timeout.Infinite + ); + + // -1 == Infinite // 0 == Already timed out (NOTE: To simulate the same behavior as sync we will only timeout on 0 if we receive an IO Pending from SNI) // >0 == Actual timeout remaining int msecsRemaining = GetTimeoutRemaining(); - int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + Debug.Assert(previousTimeoutState == TimeoutStopped, "previous timeout state was not Stopped"); if (msecsRemaining > 0) { @@ -2495,7 +2524,7 @@ internal void ReadSni(TaskCompletionSource completion) _networkPacketTaskSource.TrySetResult(null); } // Disable timeout timer on error - Interlocked.Exchange(ref _timeoutState, TimeoutStopped); + SetTimeoutStateStopped(); ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); } else if (msecsRemaining == 0) @@ -2624,7 +2653,7 @@ private void ReadSniError(TdsParserStateObject stateObj, uint error) } else { - stateObj._timeoutState = TimeoutStopped; + stateObj.SetTimeoutStateStopped(); Debug.Assert(_parser.Connection != null, "SqlConnectionInternalTds handler can not be null at this point."); AddError(new SqlError(TdsEnums.TIMEOUT_EXPIRED, (byte)0x00, TdsEnums.MIN_ERROR_CLASS, _parser.Server, _parser.Connection.TimeoutErrorInternal.GetErrorMessage(), "", 0, TdsEnums.SNI_WAIT_TIMEOUT)); @@ -2859,7 +2888,12 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) // and use cmpexch so that all changes out of the running state are atomic int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); - ProcessSniPacket(packet, error); + // if the state is anything other than running then this query has reached an end so + // set the correlation _timeoutIdentityValue to 0 to prevent late callbacks executing + if (_timeoutState != TimeoutRunning) + { + _timeoutIdentityValue = 0; + } ProcessSniPacket(packet, error); } From 31a3dbd09f0e26254f45c43107db03dd2ffda8c1 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Thu, 11 Feb 2021 19:12:00 +0000 Subject: [PATCH 04/13] remove state spare --- .../Data/SqlClient/TdsParserStateObject.cs | 28 ++++++++++--------- 1 file changed, 15 insertions(+), 13 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 4fedec53ac..de0c713ce8 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -41,6 +41,18 @@ internal enum SnapshottedStateFlags : byte AttentionReceived = 1 << 5 // NOTE: Received is not volatile as it is only ever accessed\modified by TryRun its callees (i.e. single threaded access) } + private sealed class TimeoutState + { + private readonly int _value; + + public TimeoutState(int value) + { + _value = value; + } + + public int IdentityValue => _value; + } + private const int AttentionTimeoutSeconds = 5; private static readonly ContextCallback s_readAdyncCallbackComplete = ReadAsyncCallbackComplete; @@ -120,7 +132,6 @@ internal enum SnapshottedStateFlags : byte private long _timeoutTime; // variable used for timeout computations, holds the value of the hi-res performance counter at which this request should expire private int _timeoutState; // expected to be one of the constant values TimeoutStopped, TimeoutRunning, TimeoutExpiredAsync, TimeoutExpiredSync private int _timeoutIdentitySource; - private TimeoutState _spareTimeoutState; private volatile int _timeoutIdentityValue; internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; @@ -2269,16 +2280,10 @@ public bool IsTimeoutStateExpired return state == TimeoutExpiredAsync || state == TimeoutExpiredSync; } } - - private sealed class TimeoutState - { - public int IdentityValue { get; set; } - } - private void OnTimeoutAsync(object state) { #if DEBUG - Thread.Sleep(13000); + //Thread.Sleep(13000); #endif int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; @@ -2292,8 +2297,6 @@ private void OnTimeoutAsync(object state) { Debug.WriteLine($"OnTimeoutAsync called with identity state={timeoutState.IdentityValue} but current identity is {currentIdentityValue} so it is being ignored"); } - timeoutState.IdentityValue = 0; - Interlocked.CompareExchange(ref _spareTimeoutState, timeoutState, null); } private bool OnTimeoutSync() @@ -2459,11 +2462,10 @@ internal void ReadSni(TaskCompletionSource completion) } _networkPacketTimeout?.Dispose(); - TimeoutState state = Interlocked.Exchange(ref _spareTimeoutState, null) ?? new TimeoutState(); - state.IdentityValue = _timeoutIdentityValue; + _networkPacketTimeout = ADP.UnsafeCreateTimer( new TimerCallback(OnTimeoutAsync), - state, + new TimeoutState(_timeoutIdentityValue), Timeout.Infinite, Timeout.Infinite ); From 101fafc6824fd72d230d4a76eeb44258cc6718a7 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Fri, 12 Feb 2021 09:48:36 -0800 Subject: [PATCH 05/13] Add Async API Tests for Timeout (#1) * Add Async API Tests for Timeout --- .../Data/SqlClient/TdsParserStateObject.cs | 29 ++- ....Data.SqlClient.ManualTesting.Tests.csproj | 1 + .../SQL/AsyncTest/AsyncTimeoutTest.cs | 209 ++++++++++++++++++ .../SystemDataInternals/ConnectionHelper.cs | 40 +++- .../ConnectionPoolHelper.cs | 15 +- 5 files changed, 267 insertions(+), 27 deletions(-) create mode 100644 src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 4fedec53ac..3fc29c3d52 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -125,8 +125,14 @@ internal enum SnapshottedStateFlags : byte internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; - private readonly LastIOTimer _lastSuccessfulIOTimer; - + // Below 2 properties are used to enforce timeout delays in code to + // reproduce issues related to theadpool starvation and timeout delay. + // It should always be set to false by default, and only be enabled during testing. + internal bool _enforceTimeoutDelay = false; + internal int _enforcedTimeoutDelayInMilliSeconds = 5000; + + private readonly LastIOTimer _lastSuccessfulIOTimer; + // secure password information to be stored // At maximum number of secure string that need to be stored is two; one for login password and the other for new change password private SecureString[] _securePasswords = new SecureString[2] { null, null }; @@ -1455,7 +1461,7 @@ internal bool TryReadInt16(out short value) { // The entire int16 is in the packet and in the buffer, so just return it // and take care of the counters. - buffer = _inBuff.AsSpan(_inBytesUsed,2); + buffer = _inBuff.AsSpan(_inBytesUsed, 2); _inBytesUsed += 2; _inBytesPacket -= 2; } @@ -1489,7 +1495,7 @@ internal bool TryReadInt32(out int value) } AssertValidState(); - value = (buffer[3] << 24) + (buffer[2] <<16) + (buffer[1] << 8) + buffer[0]; + value = (buffer[3] << 24) + (buffer[2] << 16) + (buffer[1] << 8) + buffer[0]; return true; } @@ -2277,9 +2283,11 @@ private sealed class TimeoutState private void OnTimeoutAsync(object state) { -#if DEBUG - Thread.Sleep(13000); -#endif + if (_enforceTimeoutDelay) + { + Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); + } + int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; if (timeoutState.IdentityValue == _timeoutIdentityValue) @@ -2467,7 +2475,7 @@ internal void ReadSni(TaskCompletionSource completion) Timeout.Infinite, Timeout.Infinite ); - + // -1 == Infinite // 0 == Already timed out (NOTE: To simulate the same behavior as sync we will only timeout on 0 if we receive an IO Pending from SNI) @@ -3555,11 +3563,10 @@ internal void SendAttention(bool mustTakeWriteLock = false) // Set _attentionSending to true before sending attention and reset after setting _attentionSent // This prevents a race condition between receiving the attention ACK and setting _attentionSent _attentionSending = true; - #if DEBUG if (!_skipSendAttention) - { #endif + { // Take lock and send attention bool releaseLock = false; if ((mustTakeWriteLock) && (!_parser.Connection.ThreadHasParserLockForClose)) @@ -3589,9 +3596,7 @@ internal void SendAttention(bool mustTakeWriteLock = false) _parser.Connection._parserLock.Release(); } } -#if DEBUG } -#endif SetTimeoutSeconds(AttentionTimeoutSeconds); // Initialize new attention timeout of 5 seconds. _attentionSent = true; diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj b/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj index 2a5bf658c5..45fc752361 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/Microsoft.Data.SqlClient.ManualTesting.Tests.csproj @@ -66,6 +66,7 @@ + diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs new file mode 100644 index 0000000000..0ba98d83b6 --- /dev/null +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs @@ -0,0 +1,209 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System; +using System.Collections; +using System.Collections.Generic; +using System.Data; +using System.Threading.Tasks; +using System.Xml; +using Microsoft.Data.SqlClient.ManualTesting.Tests.SystemDataInternals; +using Xunit; + +namespace Microsoft.Data.SqlClient.ManualTesting.Tests +{ + public static class AsyncTimeoutTest + { + static string delayQuery2s = "WAITFOR DELAY '00:00:02'"; + static string delayQuery10s = "WAITFOR DELAY '00:00:10'"; + + public enum AsyncAPI + { + ExecuteReaderAsync, + ExecuteScalarAsync, + ExecuteXmlReaderAsync + } + + [ConditionalTheory(typeof(DataTestUtility), nameof(DataTestUtility.AreConnStringsSetup))] + [ClassData(typeof(AsyncTimeoutTestVariations))] + public static void TestDelayedAsyncTimeout(AsyncAPI api, string commonObj, int delayPeriod, bool marsEnabled) => + RunTest(api, commonObj, delayPeriod, marsEnabled); + + public class AsyncTimeoutTestVariations : IEnumerable + { + public IEnumerator GetEnumerator() + { + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 0, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Connection", 0, false }; + + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 0, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Connection", 0, false }; + + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 0, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Connection", 0, false }; + + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 0, true }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteReaderAsync, "Command", 0, false }; + + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 0, true }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteScalarAsync, "Command", 0, false }; + + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 8000, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 5000, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 0, true }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 8000, false }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 5000, false }; + yield return new object[] { AsyncAPI.ExecuteXmlReaderAsync, "Command", 0, false }; + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + } + + private static void RunTest(AsyncAPI api, string commonObj, int timeoutDelay, bool marsEnabled) + { + string connString = new SqlConnectionStringBuilder(DataTestUtility.TCPConnectionString) + { + MultipleActiveResultSets = marsEnabled + }.ConnectionString; + + using (SqlConnection sqlConnection = new SqlConnection(connString)) + { + sqlConnection.Open(); + if (timeoutDelay != 0) + { + ConnectionHelper.SetEnforcedTimeout(sqlConnection, true, timeoutDelay); + } + switch (commonObj) + { + case "Connection": + QueryAndValidate(api, 1, delayQuery2s, 1, true, true, sqlConnection).Wait(); + QueryAndValidate(api, 2, delayQuery2s, 5, false, true, sqlConnection).Wait(); + QueryAndValidate(api, 3, delayQuery10s, 1, true, true, sqlConnection).Wait(); + QueryAndValidate(api, 4, delayQuery2s, 10, false, true, sqlConnection).Wait(); + break; + case "Command": + using (SqlCommand cmd = sqlConnection.CreateCommand()) + { + QueryAndValidate(api, 1, delayQuery2s, 1, true, false, sqlConnection, cmd).Wait(); + QueryAndValidate(api, 2, delayQuery2s, 5, false, false, sqlConnection, cmd).Wait(); + QueryAndValidate(api, 3, delayQuery10s, 1, true, false, sqlConnection, cmd).Wait(); + QueryAndValidate(api, 4, delayQuery2s, 10, false, false, sqlConnection, cmd).Wait(); + } + break; + } + } + } + + private static async Task QueryAndValidate(AsyncAPI api, int index, string delayQuery, int timeout, + bool timeoutExExpected = false, bool useTransaction = false, SqlConnection cn = null, SqlCommand cmd = null) + { + SqlTransaction tx = null; + try + { + if (cn != null) + { + if (cn.State != ConnectionState.Open) + { + await cn.OpenAsync(); + } + cmd = cn.CreateCommand(); + if (useTransaction) + { + tx = cn.BeginTransaction(IsolationLevel.ReadCommitted); + cmd.Transaction = tx; + } + } + + cmd.CommandTimeout = timeout; + if (api != AsyncAPI.ExecuteXmlReaderAsync) + { + cmd.CommandText = delayQuery + $";select {index} as Id;"; + } + else + { + cmd.CommandText = delayQuery + $";select {index} as Id FOR XML PATH;"; + } + + var result = -1; + switch (api) + { + case AsyncAPI.ExecuteReaderAsync: + using (SqlDataReader reader = await cmd.ExecuteReaderAsync().ConfigureAwait(false)) + { + while (await reader.ReadAsync().ConfigureAwait(false)) + { + var columnIndex = reader.GetOrdinal("Id"); + result = reader.GetInt32(columnIndex); + break; + } + } + break; + case AsyncAPI.ExecuteScalarAsync: + result = (int)await cmd.ExecuteScalarAsync().ConfigureAwait(false); + break; + case AsyncAPI.ExecuteXmlReaderAsync: + using (XmlReader reader = await cmd.ExecuteXmlReaderAsync().ConfigureAwait(false)) + { + try + { + Assert.True(reader.Settings.Async); + reader.ReadToDescendant("Id"); + result = reader.ReadElementContentAsInt(); + } + catch (Exception ex) + { + Assert.False(true, "Exception occurred: " + ex.Message); + } + } + break; + } + + if (result != index) + { + throw new Exception("High Alert! Wrong data received for index: " + index); + } + else + { + Assert.True(!timeoutExExpected && result == index); + } + } + catch (SqlException e) + { + if (!timeoutExExpected) + throw new Exception("Index " + index + " failed with: " + e.Message); + else + Assert.True(timeoutExExpected && e.Class == 11 && e.Number == -2); + } + finally + { + if (cn != null) + { + if (useTransaction) + tx.Commit(); + cn.Close(); + } + } + } + } +} diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionHelper.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionHelper.cs index 2b4f533dd5..54561e1be9 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionHelper.cs +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionHelper.cs @@ -10,15 +10,22 @@ namespace Microsoft.Data.SqlClient.ManualTesting.Tests.SystemDataInternals { internal static class ConnectionHelper { - private static Assembly s_systemDotData = Assembly.Load(new AssemblyName(typeof(SqlConnection).GetTypeInfo().Assembly.FullName)); - private static Type s_sqlConnection = s_systemDotData.GetType("Microsoft.Data.SqlClient.SqlConnection"); - private static Type s_sqlInternalConnection = s_systemDotData.GetType("Microsoft.Data.SqlClient.SqlInternalConnection"); - private static Type s_sqlInternalConnectionTds = s_systemDotData.GetType("Microsoft.Data.SqlClient.SqlInternalConnectionTds"); - private static Type s_dbConnectionInternal = s_systemDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionInternal"); + private static Assembly s_MicrosoftDotData = Assembly.Load(new AssemblyName(typeof(SqlConnection).GetTypeInfo().Assembly.FullName)); + private static Type s_sqlConnection = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.SqlConnection"); + private static Type s_sqlInternalConnection = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.SqlInternalConnection"); + private static Type s_sqlInternalConnectionTds = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.SqlInternalConnectionTds"); + private static Type s_dbConnectionInternal = s_MicrosoftDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionInternal"); + private static Type s_tdsParser = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.TdsParser"); + private static Type s_tdsParserStateObject = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.TdsParserStateObject"); private static PropertyInfo s_sqlConnectionInternalConnection = s_sqlConnection.GetProperty("InnerConnection", BindingFlags.Instance | BindingFlags.NonPublic); private static PropertyInfo s_dbConnectionInternalPool = s_dbConnectionInternal.GetProperty("Pool", BindingFlags.Instance | BindingFlags.NonPublic); private static MethodInfo s_dbConnectionInternalIsConnectionAlive = s_dbConnectionInternal.GetMethod("IsConnectionAlive", BindingFlags.Instance | BindingFlags.NonPublic); private static FieldInfo s_sqlInternalConnectionTdsParser = s_sqlInternalConnectionTds.GetField("_parser", BindingFlags.Instance | BindingFlags.NonPublic); + private static PropertyInfo s_innerConnectionProperty = s_sqlConnection.GetProperty("InnerConnection", BindingFlags.Instance | BindingFlags.NonPublic); + private static PropertyInfo s_tdsParserProperty = s_sqlInternalConnectionTds.GetProperty("Parser", BindingFlags.Instance | BindingFlags.NonPublic); + private static FieldInfo s_tdsParserStateObjectProperty = s_tdsParser.GetField("_physicalStateObj", BindingFlags.Instance | BindingFlags.NonPublic); + private static FieldInfo s_enforceTimeoutDelayProperty = s_tdsParserStateObject.GetField("_enforceTimeoutDelay", BindingFlags.Instance | BindingFlags.NonPublic); + private static FieldInfo s_enforcedTimeoutDelayInMilliSeconds = s_tdsParserStateObject.GetField("_enforcedTimeoutDelayInMilliSeconds", BindingFlags.Instance | BindingFlags.NonPublic); public static object GetConnectionPool(object internalConnection) { @@ -28,12 +35,12 @@ public static object GetConnectionPool(object internalConnection) public static object GetInternalConnection(this SqlConnection connection) { + VerifyObjectIsConnection(connection); object internalConnection = s_sqlConnectionInternalConnection.GetValue(connection, null); Debug.Assert(((internalConnection != null) && (s_dbConnectionInternal.IsInstanceOfType(internalConnection))), "Connection provided has an invalid internal connection"); return internalConnection; } - public static bool IsConnectionAlive(object internalConnection) { VerifyObjectIsInternalConnection(internalConnection); @@ -45,7 +52,15 @@ private static void VerifyObjectIsInternalConnection(object internalConnection) if (internalConnection == null) throw new ArgumentNullException(nameof(internalConnection)); if (!s_dbConnectionInternal.IsInstanceOfType(internalConnection)) - throw new ArgumentException("Object provided was not a DbConnectionInternal", "internalConnection"); + throw new ArgumentException("Object provided was not a DbConnectionInternal", nameof(internalConnection)); + } + + private static void VerifyObjectIsConnection(object connection) + { + if (connection == null) + throw new ArgumentNullException(nameof(connection)); + if (!s_sqlConnection.IsInstanceOfType(connection)) + throw new ArgumentException("Object provided was not a SqlConnection", nameof(connection)); } public static object GetParser(object internalConnection) @@ -53,5 +68,16 @@ public static object GetParser(object internalConnection) VerifyObjectIsInternalConnection(internalConnection); return s_sqlInternalConnectionTdsParser.GetValue(internalConnection); } + + public static void SetEnforcedTimeout(this SqlConnection connection, bool enforce, int timeout) + { + VerifyObjectIsConnection(connection); + var stateObj = s_tdsParserStateObjectProperty.GetValue( + s_tdsParserProperty.GetValue( + s_innerConnectionProperty.GetValue( + connection, null), null)); + s_enforceTimeoutDelayProperty.SetValue(stateObj, enforce); + s_enforcedTimeoutDelayInMilliSeconds.SetValue(stateObj, timeout); + } } } diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionPoolHelper.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionPoolHelper.cs index 6ae73f5571..d7c5471427 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionPoolHelper.cs +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/Common/SystemDataInternals/ConnectionPoolHelper.cs @@ -13,13 +13,13 @@ namespace Microsoft.Data.SqlClient.ManualTesting.Tests.SystemDataInternals { internal static class ConnectionPoolHelper { - private static Assembly s_systemDotData = Assembly.Load(new AssemblyName(typeof(SqlConnection).GetTypeInfo().Assembly.FullName)); - private static Type s_dbConnectionPool = s_systemDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPool"); - private static Type s_dbConnectionPoolGroup = s_systemDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPoolGroup"); - private static Type s_dbConnectionPoolIdentity = s_systemDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPoolIdentity"); - private static Type s_dbConnectionFactory = s_systemDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionFactory"); - private static Type s_sqlConnectionFactory = s_systemDotData.GetType("Microsoft.Data.SqlClient.SqlConnectionFactory"); - private static Type s_dbConnectionPoolKey = s_systemDotData.GetType("Microsoft.Data.Common.DbConnectionPoolKey"); + private static Assembly s_MicrosoftDotData = Assembly.Load(new AssemblyName(typeof(SqlConnection).GetTypeInfo().Assembly.FullName)); + private static Type s_dbConnectionPool = s_MicrosoftDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPool"); + private static Type s_dbConnectionPoolGroup = s_MicrosoftDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPoolGroup"); + private static Type s_dbConnectionPoolIdentity = s_MicrosoftDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionPoolIdentity"); + private static Type s_dbConnectionFactory = s_MicrosoftDotData.GetType("Microsoft.Data.ProviderBase.DbConnectionFactory"); + private static Type s_sqlConnectionFactory = s_MicrosoftDotData.GetType("Microsoft.Data.SqlClient.SqlConnectionFactory"); + private static Type s_dbConnectionPoolKey = s_MicrosoftDotData.GetType("Microsoft.Data.Common.DbConnectionPoolKey"); private static Type s_dictStringPoolGroup = typeof(Dictionary<,>).MakeGenericType(s_dbConnectionPoolKey, s_dbConnectionPoolGroup); private static Type s_dictPoolIdentityPool = typeof(ConcurrentDictionary<,>).MakeGenericType(s_dbConnectionPoolIdentity, s_dbConnectionPool); private static PropertyInfo s_dbConnectionPoolCount = s_dbConnectionPool.GetProperty("Count", BindingFlags.Instance | BindingFlags.NonPublic); @@ -123,7 +123,6 @@ internal static int CountConnectionsInPool(object pool) return (int)s_dbConnectionPoolCount.GetValue(pool, null); } - private static void VerifyObjectIsPool(object pool) { if (pool == null) From 8debbf7da571bdae30c39a5c9b06c4c4665894ef Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Fri, 12 Feb 2021 17:58:13 +0000 Subject: [PATCH 06/13] fixup ifdes --- .../src/Microsoft/Data/SqlClient/TdsParserStateObject.cs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 81a97b70b9..92d2160a39 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -3568,6 +3568,7 @@ internal void SendAttention(bool mustTakeWriteLock = false) #if DEBUG if (!_skipSendAttention) { +#endif // Take lock and send attention bool releaseLock = false; if ((mustTakeWriteLock) && (!_parser.Connection.ThreadHasParserLockForClose)) @@ -3597,7 +3598,9 @@ internal void SendAttention(bool mustTakeWriteLock = false) _parser.Connection._parserLock.Release(); } } - } +#if DEBUG + } +#endif SetTimeoutSeconds(AttentionTimeoutSeconds); // Initialize new attention timeout of 5 seconds. _attentionSent = true; From 1a7a3b061dec44ce7c342b8126e0577e9b0d8e88 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Fri, 12 Feb 2021 19:51:57 +0000 Subject: [PATCH 07/13] revert debug comment in sni packet --- .../netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs index 43debdb43c..857a300259 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/SNI/SNIPacket.cs @@ -75,7 +75,7 @@ public SNIPacket(SNIHandle owner,int id) { if (_data != null) { - //Debug.Fail($@"finalizer called for unreleased SNIPacket, tag: {_traceTag}"); + Debug.Fail($@"finalizer called for unreleased SNIPacket, tag: {_traceTag}"); } } From b9e83acde6176b87a81a778c472295e56d42bde4 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Fri, 12 Feb 2021 20:37:27 +0000 Subject: [PATCH 08/13] netfx changes --- .../Microsoft/Data/SqlClient/SqlBulkCopy.cs | 2 +- .../Microsoft/Data/SqlClient/SqlDataReader.cs | 2 +- .../src/Microsoft/Data/SqlClient/TdsParser.cs | 4 +- .../Data/SqlClient/TdsParserStateObject.cs | 146 ++++++++++++++++-- 4 files changed, 135 insertions(+), 19 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs index f95a76348d..1a463f1f5d 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlBulkCopy.cs @@ -3039,7 +3039,7 @@ private void CleanUpStateObject(bool isCancelRequested = true) { _stateObj.CancelRequest(); } - _stateObj._internalTimeout = false; + _stateObj.SetTimeoutStateStopped(); _stateObj.CloseSession(); _stateObj._bulkCopyOpperationInProgress = false; _stateObj._bulkCopyWriteTimeout = false; diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlDataReader.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlDataReader.cs index 176b3ddf3c..b453bbc52a 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlDataReader.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/SqlDataReader.cs @@ -1067,7 +1067,7 @@ private bool TryCloseInternal(bool closeReader) { _sharedState._dataReady = true; // set _sharedState._dataReady to not confuse CleanPartialRead } - _stateObj._internalTimeout = false; + _stateObj.SetTimeoutStateStopped(); if (_sharedState._dataReady) { cleanDataFailed = true; diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParser.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParser.cs index bd5f08f8ea..3ca7ff3f8b 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParser.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParser.cs @@ -2262,7 +2262,7 @@ internal bool TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataRead // If there is data ready, but we didn't exit the loop, then something is wrong Debug.Assert(!dataReady, "dataReady not expected - did we forget to skip the row?"); - if (stateObj._internalTimeout) + if (stateObj.IsTimeoutStateExpired) { runBehavior = RunBehavior.Attention; } @@ -2891,7 +2891,7 @@ internal bool TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataRead stateObj._attentionSent = false; stateObj._attentionReceived = false; - if (RunBehavior.Clean != (RunBehavior.Clean & runBehavior) && !stateObj._internalTimeout) + if (RunBehavior.Clean != (RunBehavior.Clean & runBehavior) && !stateObj.IsTimeoutStateExpired) { // Add attention error to collection - if not RunBehavior.Clean! stateObj.AddError(new SqlError(0, 0, TdsEnums.MIN_ERROR_CLASS, _server, SQLMessage.OperationCancelled(), "", 0)); diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 7e526ebd9c..747a34e0b4 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -24,7 +24,12 @@ sealed internal class LastIOTimer sealed internal class TdsParserStateObject { - const int AttentionTimeoutSeconds = 5; + private const int TimeoutStopped = 0; + private const int TimeoutRunning = 1; + private const int TimeoutExpiredAsync = 2; + private const int TimeoutExpiredSync = 3; + + private const int AttentionTimeoutSeconds = 5; // Ticks to consider a connection "good" after a successful I/O (10,000 ticks = 1 ms) // The resolution of the timer is typically in the range 10 to 16 milliseconds according to msdn. @@ -33,6 +38,18 @@ sealed internal class TdsParserStateObject // of very small open, query, close loops. private const long CheckConnectionWindow = 50000; + private sealed class TimeoutState + { + private readonly int _value; + + public TimeoutState(int value) + { + _value = value; + } + + public int IdentityValue => _value; + } + private static int _objectTypeCount; // EventSource Counter internal readonly int _objectID = System.Threading.Interlocked.Increment(ref _objectTypeCount); @@ -103,10 +120,19 @@ internal int ObjectID // Timeout variables private long _timeoutMilliseconds; private long _timeoutTime; // variable used for timeout computations, holds the value of the hi-res performance counter at which this request should expire + private int _timeoutState; // expected to be one of the constant values TimeoutStopped, TimeoutRunning, TimeoutExpiredAsync, TimeoutExpiredSync + private int _timeoutIdentitySource; + private volatile int _timeoutIdentityValue; internal volatile bool _attentionSent = false; // true if we sent an Attention to the server internal bool _attentionReceived = false; // NOTE: Received is not volatile as it is only ever accessed\modified by TryRun its callees (i.e. single threaded access) internal volatile bool _attentionSending = false; - internal bool _internalTimeout = false; // an internal timeout occurred + + // Below 2 properties are used to enforce timeout delays in code to + // reproduce issues related to theadpool starvation and timeout delay. + // It should always be set to false by default, and only be enabled during testing. + internal bool _enforceTimeoutDelay = false; + internal int _enforcedTimeoutDelayInMilliSeconds = 5000; + private readonly LastIOTimer _lastSuccessfulIOTimer; // secure password information to be stored @@ -804,7 +830,7 @@ private void ResetCancelAndProcessAttention() } #endif //DEBUG } - _internalTimeout = false; + SetTimeoutStateStopped(); } } @@ -1155,7 +1181,7 @@ internal bool TryProcessHeader() return false; } - if (_internalTimeout) + if (IsTimeoutStateExpired) { ThrowExceptionAndWarning(); // TODO: see the comment above @@ -2328,11 +2354,62 @@ internal void OnConnectionClosed() } - private void OnTimeout(object state) + public void SetTimeoutStateStopped() + { + Interlocked.Exchange(ref _timeoutState, TimeoutStopped); + _timeoutIdentityValue = 0; + } + + public bool IsTimeoutStateExpired + { + get + { + int state = _timeoutState; + return state == TimeoutExpiredAsync || state == TimeoutExpiredSync; + } + } + + private void OnTimeoutAsync(object state) { - if (!_internalTimeout) + if (_enforceTimeoutDelay) + { + Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); + } + + int currentIdentityValue = _timeoutIdentityValue; + TimeoutState timeoutState = (TimeoutState)state; + if (timeoutState.IdentityValue == _timeoutIdentityValue) { - _internalTimeout = true; + // the return value is not useful here because no choice is going to be made using it + // we only want to make this call to set the state knowing that it will be seen later + OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); + } + else + { + Debug.WriteLine($"OnTimeoutAsync called with identity state={timeoutState.IdentityValue} but current identity is {currentIdentityValue} so it is being ignored"); + } + } + + private bool OnTimeoutSync() + { + return OnTimeoutCore(TimeoutRunning, TimeoutExpiredSync); + } + + /// + /// attempts to change the timout state from the expected state to the target state and if it succeeds + /// will setup the the stateobject into the timeout expired state + /// + /// the state that is the expected current state, state will change only if this is correct + /// the state that will be changed to if the expected state is correct + /// boolean value indicating whether the call changed the timeout state + private bool OnTimeoutCore(int expectedState, int targetState) + { + Debug.Assert(targetState == TimeoutExpiredAsync || targetState == TimeoutExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); + + bool retval = false; + if (Interlocked.CompareExchange(ref _timeoutState, targetState, expectedState) == expectedState) + { + retval = true; // lock protects against Close and Cancel lock (this) { @@ -2432,6 +2509,7 @@ private void OnTimeout(object state) } } } + return retval; } internal void ReadSni(TaskCompletionSource completion) @@ -2464,15 +2542,31 @@ internal void ReadSni(TaskCompletionSource completion) { Debug.Assert(completion != null, "Async on but null asyncResult passed"); - if (_networkPacketTimeout == null) + // if the state is currently stopped then change it to running and allocate a new identity value from + // the identity source. The identity value is used to correlate timer callback events to the currently + // running timeout and prevents a late timer callback affecting a result it does not relate to + int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + if (previousTimeoutState == TimeoutStopped) { - _networkPacketTimeout = new Timer(OnTimeout, null, Timeout.Infinite, Timeout.Infinite); + Debug.Assert(_timeoutIdentityValue == 0, "timer was previously stopped without resetting the _identityValue"); + _timeoutIdentityValue = Interlocked.Increment(ref _timeoutIdentitySource); } + _networkPacketTimeout?.Dispose(); + + _networkPacketTimeout = new Timer( + new TimerCallback(OnTimeoutAsync), + new TimeoutState(_timeoutIdentityValue), + Timeout.Infinite, + Timeout.Infinite + ); + // -1 == Infinite // 0 == Already timed out (NOTE: To simulate the same behavior as sync we will only timeout on 0 if we receive an IO Pending from SNI) // >0 == Actual timeout remaining int msecsRemaining = GetTimeoutRemaining(); + + Debug.Assert(previousTimeoutState == TimeoutStopped, "previous timeout state was not Stopped"); if (msecsRemaining > 0) { ChangeNetworkPacketTimeout(msecsRemaining, Timeout.Infinite); @@ -2529,12 +2623,15 @@ internal void ReadSni(TaskCompletionSource completion) _networkPacketTaskSource.TrySetResult(null); } // Disable timeout timer on error + SetTimeoutStateStopped(); ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); } else if (msecsRemaining == 0) - { // Got IO Pending, but we have no time left to wait - // Immediately schedule the timeout timer to fire - ChangeNetworkPacketTimeout(0, Timeout.Infinite); + { + // Got IO Pending, but we have no time left to wait + // disable the timer and set the error state by calling OnTimeoutSync + ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); + OnTimeoutSync(); } // DO NOT HANDLE PENDING READ HERE - which is TdsEnums.SNI_SUCCESS_IO_PENDING state. // That is handled by user who initiated async read, or by ReadNetworkPacket which is sync over async. @@ -2672,13 +2769,13 @@ private void ReadSniError(TdsParserStateObject stateObj, UInt32 error) Debug.Assert(_syncOverAsync, "Should never reach here with async on!"); bool fail = false; - if (_internalTimeout) + if (IsTimeoutStateExpired) { // This is now our second timeout - time to give up. fail = true; } else { - stateObj._internalTimeout = true; + stateObj.SetTimeoutStateStopped(); Debug.Assert(_parser.Connection != null, "SqlConnectionInternalTds handler can not be null at this point."); AddError(new SqlError(TdsEnums.TIMEOUT_EXPIRED, (byte)0x00, TdsEnums.MIN_ERROR_CLASS, _parser.Server, _parser.Connection.TimeoutErrorInternal.GetErrorMessage(), "", 0, TdsEnums.SNI_WAIT_TIMEOUT)); @@ -2876,6 +2973,25 @@ public void ReadAsyncCallback(IntPtr key, IntPtr packet, UInt32 error) ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); + // the timer thread may be unreliable under high contention scenarios it cannot be + // assumed that the timeout has happened on the timer thread callback, check the timeout + // synchrnously and then call OnTimeoutSync to force an atomic change of state + if (TimeoutHasExpired) + { + OnTimeoutSync(); + } + + // try to change to the stopped state but only do so if currently in the running state + // and use cmpexch so that all changes out of the running state are atomic + int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + + // if the state is anything other than running then this query has reached an end so + // set the correlation _timeoutIdentityValue to 0 to prevent late callbacks executing + if (_timeoutState != TimeoutRunning) + { + _timeoutIdentityValue = 0; + } + ProcessSniPacket(packet, error); } catch (Exception e) @@ -4011,7 +4127,7 @@ internal void AssertStateIsClean() // Attention\Cancellation\Timeouts Debug.Assert(!_attentionReceived && !_attentionSent && !_attentionSending, $"StateObj is still dealing with attention: Sent: {_attentionSent}, Received: {_attentionReceived}, Sending: {_attentionSending}"); Debug.Assert(!_cancelled, "StateObj still has cancellation set"); - Debug.Assert(!_internalTimeout, "StateObj still has internal timeout set"); + Debug.Assert(_timeoutState == TimeoutStopped, "StateObj still has internal timeout set"); // Errors and Warnings Debug.Assert(!_hasErrorOrWarning, "StateObj still has stored errors or warnings"); } From ea126e079167eb2fb1938184362d299dc35370a3 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Wed, 17 Feb 2021 22:10:53 +0000 Subject: [PATCH 09/13] move state constants into TimeoutState class --- .../Data/SqlClient/TdsParserStateObject.cs | 32 +++++++++---------- 1 file changed, 16 insertions(+), 16 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 92d2160a39..5f6190b008 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -22,11 +22,6 @@ sealed internal class LastIOTimer internal abstract class TdsParserStateObject { - private const int TimeoutStopped = 0; - private const int TimeoutRunning = 1; - private const int TimeoutExpiredAsync = 2; - private const int TimeoutExpiredSync = 3; - private static int _objectTypeCount; // EventSource counter internal readonly int _objectID = Interlocked.Increment(ref _objectTypeCount); @@ -43,6 +38,11 @@ internal enum SnapshottedStateFlags : byte private sealed class TimeoutState { + public const int Stopped = 0; + public const int Running = 1; + public const int ExpiredAsync = 2; + public const int ExpiredSync = 3; + private readonly int _value; public TimeoutState(int value) @@ -2274,7 +2274,7 @@ internal void OnConnectionClosed() public void SetTimeoutStateStopped() { - Interlocked.Exchange(ref _timeoutState, TimeoutStopped); + Interlocked.Exchange(ref _timeoutState, TimeoutState.Stopped); _timeoutIdentityValue = 0; } @@ -2283,7 +2283,7 @@ public bool IsTimeoutStateExpired get { int state = _timeoutState; - return state == TimeoutExpiredAsync || state == TimeoutExpiredSync; + return state == TimeoutState.ExpiredAsync || state == TimeoutState.ExpiredSync; } } private void OnTimeoutAsync(object state) @@ -2299,7 +2299,7 @@ private void OnTimeoutAsync(object state) { // the return value is not useful here because no choice is going to be made using it // we only want to make this call to set the state knowing that it will be seen later - OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); + OnTimeoutCore(TimeoutState.Running, TimeoutState.ExpiredAsync); } else { @@ -2309,7 +2309,7 @@ private void OnTimeoutAsync(object state) private bool OnTimeoutSync() { - return OnTimeoutCore(TimeoutRunning, TimeoutExpiredSync); + return OnTimeoutCore(TimeoutState.Running, TimeoutState.ExpiredSync); } /// @@ -2321,7 +2321,7 @@ private bool OnTimeoutSync() /// boolean value indicating whether the call changed the timeout state private bool OnTimeoutCore(int expectedState, int targetState) { - Debug.Assert(targetState == TimeoutExpiredAsync || targetState == TimeoutExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); + Debug.Assert(targetState == TimeoutState.ExpiredAsync || targetState == TimeoutState.ExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); bool retval = false; if (Interlocked.CompareExchange(ref _timeoutState, targetState, expectedState) == expectedState) @@ -2462,8 +2462,8 @@ internal void ReadSni(TaskCompletionSource completion) // if the state is currently stopped then change it to running and allocate a new identity value from // the identity source. The identity value is used to correlate timer callback events to the currently // running timeout and prevents a late timer callback affecting a result it does not relate to - int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); - if (previousTimeoutState == TimeoutStopped) + int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutState.Running, TimeoutState.Stopped); + if (previousTimeoutState == TimeoutState.Stopped) { Debug.Assert(_timeoutIdentityValue == 0, "timer was previously stopped without resetting the _identityValue"); _timeoutIdentityValue = Interlocked.Increment(ref _timeoutIdentitySource); @@ -2484,7 +2484,7 @@ internal void ReadSni(TaskCompletionSource completion) // >0 == Actual timeout remaining int msecsRemaining = GetTimeoutRemaining(); - Debug.Assert(previousTimeoutState == TimeoutStopped, "previous timeout state was not Stopped"); + Debug.Assert(previousTimeoutState == TimeoutState.Stopped, "previous timeout state was not Stopped"); if (msecsRemaining > 0) { ChangeNetworkPacketTimeout(msecsRemaining, Timeout.Infinite); @@ -2896,11 +2896,11 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) // try to change to the stopped state but only do so if currently in the running state // and use cmpexch so that all changes out of the running state are atomic - int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutState.Running, TimeoutState.Stopped); // if the state is anything other than running then this query has reached an end so // set the correlation _timeoutIdentityValue to 0 to prevent late callbacks executing - if (_timeoutState != TimeoutRunning) + if (_timeoutState != TimeoutState.Running) { _timeoutIdentityValue = 0; } @@ -3972,7 +3972,7 @@ internal void AssertStateIsClean() // Attention\Cancellation\Timeouts Debug.Assert(!HasReceivedAttention && !_attentionSent && !_attentionSending, $"StateObj is still dealing with attention: Sent: {_attentionSent}, Received: {HasReceivedAttention}, Sending: {_attentionSending}"); Debug.Assert(!_cancelled, "StateObj still has cancellation set"); - Debug.Assert(_timeoutState == TimeoutStopped, "StateObj still has internal timeout set"); + Debug.Assert(_timeoutState == TimeoutState.Stopped, "StateObj still has internal timeout set"); // Errors and Warnings Debug.Assert(!_hasErrorOrWarning, "StateObj still has stored errors or warnings"); } From b357e860f777f93372be43d57fbb200336d64ab5 Mon Sep 17 00:00:00 2001 From: Wraith2 Date: Wed, 17 Feb 2021 22:17:58 +0000 Subject: [PATCH 10/13] move state constants into TimeoutState class netfx --- .../Data/SqlClient/TdsParserStateObject.cs | 32 ++++++++++--------- 1 file changed, 17 insertions(+), 15 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 747a34e0b4..c50044b728 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -24,10 +24,7 @@ sealed internal class LastIOTimer sealed internal class TdsParserStateObject { - private const int TimeoutStopped = 0; - private const int TimeoutRunning = 1; - private const int TimeoutExpiredAsync = 2; - private const int TimeoutExpiredSync = 3; + private const int AttentionTimeoutSeconds = 5; @@ -40,6 +37,11 @@ sealed internal class TdsParserStateObject private sealed class TimeoutState { + public const int Stopped = 0; + public const int Running = 1; + public const int ExpiredAsync = 2; + public const int ExpiredSync = 3; + private readonly int _value; public TimeoutState(int value) @@ -2356,7 +2358,7 @@ internal void OnConnectionClosed() public void SetTimeoutStateStopped() { - Interlocked.Exchange(ref _timeoutState, TimeoutStopped); + Interlocked.Exchange(ref _timeoutState, TimeoutState.Stopped); _timeoutIdentityValue = 0; } @@ -2365,7 +2367,7 @@ public bool IsTimeoutStateExpired get { int state = _timeoutState; - return state == TimeoutExpiredAsync || state == TimeoutExpiredSync; + return state == TimeoutState.ExpiredAsync || state == TimeoutState.ExpiredSync; } } @@ -2382,7 +2384,7 @@ private void OnTimeoutAsync(object state) { // the return value is not useful here because no choice is going to be made using it // we only want to make this call to set the state knowing that it will be seen later - OnTimeoutCore(TimeoutRunning, TimeoutExpiredAsync); + OnTimeoutCore(TimeoutState.Running, TimeoutState.ExpiredAsync); } else { @@ -2392,7 +2394,7 @@ private void OnTimeoutAsync(object state) private bool OnTimeoutSync() { - return OnTimeoutCore(TimeoutRunning, TimeoutExpiredSync); + return OnTimeoutCore(TimeoutState.Running, TimeoutState.ExpiredSync); } /// @@ -2404,7 +2406,7 @@ private bool OnTimeoutSync() /// boolean value indicating whether the call changed the timeout state private bool OnTimeoutCore(int expectedState, int targetState) { - Debug.Assert(targetState == TimeoutExpiredAsync || targetState == TimeoutExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); + Debug.Assert(targetState == TimeoutState.ExpiredAsync || targetState == TimeoutState.ExpiredSync, "OnTimeoutCore must have an expiry state as the targetState"); bool retval = false; if (Interlocked.CompareExchange(ref _timeoutState, targetState, expectedState) == expectedState) @@ -2545,8 +2547,8 @@ internal void ReadSni(TaskCompletionSource completion) // if the state is currently stopped then change it to running and allocate a new identity value from // the identity source. The identity value is used to correlate timer callback events to the currently // running timeout and prevents a late timer callback affecting a result it does not relate to - int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); - if (previousTimeoutState == TimeoutStopped) + int previousTimeoutState = Interlocked.CompareExchange(ref _timeoutState, TimeoutState.Running, TimeoutState.Stopped); + if (previousTimeoutState == TimeoutState.Stopped) { Debug.Assert(_timeoutIdentityValue == 0, "timer was previously stopped without resetting the _identityValue"); _timeoutIdentityValue = Interlocked.Increment(ref _timeoutIdentitySource); @@ -2566,7 +2568,7 @@ internal void ReadSni(TaskCompletionSource completion) // >0 == Actual timeout remaining int msecsRemaining = GetTimeoutRemaining(); - Debug.Assert(previousTimeoutState == TimeoutStopped, "previous timeout state was not Stopped"); + Debug.Assert(previousTimeoutState == TimeoutState.Stopped, "previous timeout state was not Stopped"); if (msecsRemaining > 0) { ChangeNetworkPacketTimeout(msecsRemaining, Timeout.Infinite); @@ -2983,11 +2985,11 @@ public void ReadAsyncCallback(IntPtr key, IntPtr packet, UInt32 error) // try to change to the stopped state but only do so if currently in the running state // and use cmpexch so that all changes out of the running state are atomic - int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutRunning, TimeoutStopped); + int previousState = Interlocked.CompareExchange(ref _timeoutState, TimeoutState.Running, TimeoutState.Stopped); // if the state is anything other than running then this query has reached an end so // set the correlation _timeoutIdentityValue to 0 to prevent late callbacks executing - if (_timeoutState != TimeoutRunning) + if (_timeoutState != TimeoutState.Running) { _timeoutIdentityValue = 0; } @@ -4127,7 +4129,7 @@ internal void AssertStateIsClean() // Attention\Cancellation\Timeouts Debug.Assert(!_attentionReceived && !_attentionSent && !_attentionSending, $"StateObj is still dealing with attention: Sent: {_attentionSent}, Received: {_attentionReceived}, Sending: {_attentionSending}"); Debug.Assert(!_cancelled, "StateObj still has cancellation set"); - Debug.Assert(_timeoutState == TimeoutStopped, "StateObj still has internal timeout set"); + Debug.Assert(_timeoutState == TimeoutState.Stopped, "StateObj still has internal timeout set"); // Errors and Warnings Debug.Assert(!_hasErrorOrWarning, "StateObj still has stored errors or warnings"); } From 4e4a7f8ce37b3e49e485784b28c427ae615787e9 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Wed, 17 Feb 2021 14:43:52 -0800 Subject: [PATCH 11/13] Introduce "TestEnabled" flag for testing async timeout tests --- BUILDGUIDE.md | 5 +++++ build.proj | 3 ++- .../netcore/src/Microsoft.Data.SqlClient.csproj | 1 + .../Microsoft/Data/SqlClient/TdsParserStateObject.cs | 5 ++++- .../netfx/src/Microsoft.Data.SqlClient.csproj | 1 + .../Microsoft/Data/SqlClient/TdsParserStateObject.cs | 6 +++++- .../ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs | 10 +++++++++- 7 files changed, 27 insertions(+), 4 deletions(-) diff --git a/BUILDGUIDE.md b/BUILDGUIDE.md index b9879fb64c..8103b27d02 100644 --- a/BUILDGUIDE.md +++ b/BUILDGUIDE.md @@ -24,6 +24,11 @@ Once the environment is setup properly, execute the desired set of commands belo # Builds the driver in 'Release' Configuration. ``` +```bash +> msbuild /p:Configuration=Release /p:TestEnabled=true +# Builds the driver in 'Release' Configuration with explicit code changes enabled for testing. +``` + ```bash > msbuild /p:Platform=Win32 # Builds the .NET Framework (NetFx) driver for Win32 (x86) platform on Windows. diff --git a/build.proj b/build.proj index 428008a4a8..72f0e7ce16 100644 --- a/build.proj +++ b/build.proj @@ -12,10 +12,11 @@ true false + false Windows Unix true - Configuration=$(Configuration);AssemblyFileVersion=$(AssemblyFileVersion);TargetsWindows=$(TargetsWindows);TargetsUnix=$(TargetsUnix); + Configuration=$(Configuration);AssemblyFileVersion=$(AssemblyFileVersion);TargetsWindows=$(TargetsWindows);TargetsUnix=$(TargetsUnix);TestEnabled=$(TestEnabled); BuildProjectReferences=false;$(ProjectProperties); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj index 3e7db7d945..3de9aa3dce 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj @@ -11,6 +11,7 @@ false netcoreapp netstandard + $(DefineConstants);TEST_ENABLED; Debug;Release;netcoreapp2.1-Debug;netcoreapp2.1-Release;netcoreapp3.1-Debug;netcoreapp3.1-Release AnyCPU;x64;x86 $(ObjFolder)$(Configuration).$(Platform)\$(AssemblyName)\netcore\ diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 5f6190b008..2c183e58ff 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -136,11 +136,13 @@ public TimeoutState(int value) internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; +#if TEST_ENABLED // Below 2 properties are used to enforce timeout delays in code to // reproduce issues related to theadpool starvation and timeout delay. // It should always be set to false by default, and only be enabled during testing. internal bool _enforceTimeoutDelay = false; internal int _enforcedTimeoutDelayInMilliSeconds = 5000; +#endif private readonly LastIOTimer _lastSuccessfulIOTimer; @@ -2288,11 +2290,12 @@ public bool IsTimeoutStateExpired } private void OnTimeoutAsync(object state) { +#if TEST_ENABLED if (_enforceTimeoutDelay) { Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); } - +#endif int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; if (timeoutState.IdentityValue == _timeoutIdentityValue) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj index cf8c458f2e..c26373ba1a 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj @@ -21,6 +21,7 @@ We should remove ResolveComReferenceSilent as soon as we can remove the dependency on mscoree. --> True $(DefineConstants);NETFRAMEWORK; + $(DefineConstants);TEST_ENABLED; $([System.IO.Path]::Combine('$(IntermediateOutputPath)','$(GeneratedSourceFileName)')) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index c50044b728..c9e4cf4aab 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -129,11 +129,13 @@ internal int ObjectID internal bool _attentionReceived = false; // NOTE: Received is not volatile as it is only ever accessed\modified by TryRun its callees (i.e. single threaded access) internal volatile bool _attentionSending = false; +#if TEST_ENABLED // Below 2 properties are used to enforce timeout delays in code to // reproduce issues related to theadpool starvation and timeout delay. // It should always be set to false by default, and only be enabled during testing. internal bool _enforceTimeoutDelay = false; internal int _enforcedTimeoutDelayInMilliSeconds = 5000; +#endif private readonly LastIOTimer _lastSuccessfulIOTimer; @@ -2373,11 +2375,13 @@ public bool IsTimeoutStateExpired private void OnTimeoutAsync(object state) { + +#if TEST_ENABLED if (_enforceTimeoutDelay) { Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); } - +#endif int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; if (timeoutState.IdentityValue == _timeoutIdentityValue) diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs index 0ba98d83b6..664d528646 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs @@ -92,7 +92,15 @@ private static void RunTest(AsyncAPI api, string commonObj, int timeoutDelay, bo sqlConnection.Open(); if (timeoutDelay != 0) { - ConnectionHelper.SetEnforcedTimeout(sqlConnection, true, timeoutDelay); + try + { + + ConnectionHelper.SetEnforcedTimeout(sqlConnection, true, timeoutDelay); + } + catch + { + Assert.False(true, "Driver does not support explicit timeout delay support. Build all configurations with `/p:TestEnabled=true` property specified."); + } } switch (commonObj) { From 9ecaf9db785fa950e57828319ee110b97caa89b7 Mon Sep 17 00:00:00 2001 From: Wraith Date: Fri, 19 Feb 2021 00:30:16 +0000 Subject: [PATCH 12/13] Apply suggestions from code review Co-authored-by: David Engel --- .../src/Microsoft/Data/SqlClient/TdsParserStateObject.cs | 7 ++++--- .../src/Microsoft/Data/SqlClient/TdsParserStateObject.cs | 8 +++----- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index 2c183e58ff..cc8fc4cb8d 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -2288,6 +2288,7 @@ public bool IsTimeoutStateExpired return state == TimeoutState.ExpiredAsync || state == TimeoutState.ExpiredSync; } } + private void OnTimeoutAsync(object state) { #if TEST_ENABLED @@ -2889,9 +2890,9 @@ public void ReadAsyncCallback(IntPtr key, PacketHandle packet, uint error) ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); - // the timer thread may be unreliable under high contention scenarios it cannot be - // assumed that the timeout has happened on the timer thread callback, check the timeout - // synchrnously and then call OnTimeoutSync to force an atomic change of state + // The timer thread may be unreliable under high contention scenarios. It cannot be + // assumed that the timeout has happened on the timer thread callback. Check the timeout + // synchrnously and then call OnTimeoutSync to force an atomic change of state. if (TimeoutHasExpired) { OnTimeoutSync(); diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index c9e4cf4aab..e8596baab9 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -24,8 +24,6 @@ sealed internal class LastIOTimer sealed internal class TdsParserStateObject { - - private const int AttentionTimeoutSeconds = 5; // Ticks to consider a connection "good" after a successful I/O (10,000 ticks = 1 ms) @@ -2979,9 +2977,9 @@ public void ReadAsyncCallback(IntPtr key, IntPtr packet, UInt32 error) ChangeNetworkPacketTimeout(Timeout.Infinite, Timeout.Infinite); - // the timer thread may be unreliable under high contention scenarios it cannot be - // assumed that the timeout has happened on the timer thread callback, check the timeout - // synchrnously and then call OnTimeoutSync to force an atomic change of state + // The timer thread may be unreliable under high contention scenarios. It cannot be + // assumed that the timeout has happened on the timer thread callback. Check the timeout + // synchrnously and then call OnTimeoutSync to force an atomic change of state. if (TimeoutHasExpired) { OnTimeoutSync(); From 98668d7ea10c2804592d737169ba918885876985 Mon Sep 17 00:00:00 2001 From: Cheena Malhotra Date: Fri, 19 Feb 2021 14:48:32 -0800 Subject: [PATCH 13/13] Revert "Introduce "TestEnabled" flag for testing async timeout tests" as per discussions. This reverts commit 4e4a7f8ce37b3e49e485784b28c427ae615787e9. --- BUILDGUIDE.md | 5 ----- build.proj | 3 +-- .../netcore/src/Microsoft.Data.SqlClient.csproj | 1 - .../Microsoft/Data/SqlClient/TdsParserStateObject.cs | 5 +---- .../netfx/src/Microsoft.Data.SqlClient.csproj | 1 - .../Microsoft/Data/SqlClient/TdsParserStateObject.cs | 6 +----- .../ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs | 10 +--------- 7 files changed, 4 insertions(+), 27 deletions(-) diff --git a/BUILDGUIDE.md b/BUILDGUIDE.md index 8103b27d02..b9879fb64c 100644 --- a/BUILDGUIDE.md +++ b/BUILDGUIDE.md @@ -24,11 +24,6 @@ Once the environment is setup properly, execute the desired set of commands belo # Builds the driver in 'Release' Configuration. ``` -```bash -> msbuild /p:Configuration=Release /p:TestEnabled=true -# Builds the driver in 'Release' Configuration with explicit code changes enabled for testing. -``` - ```bash > msbuild /p:Platform=Win32 # Builds the .NET Framework (NetFx) driver for Win32 (x86) platform on Windows. diff --git a/build.proj b/build.proj index 72f0e7ce16..428008a4a8 100644 --- a/build.proj +++ b/build.proj @@ -12,11 +12,10 @@ true false - false Windows Unix true - Configuration=$(Configuration);AssemblyFileVersion=$(AssemblyFileVersion);TargetsWindows=$(TargetsWindows);TargetsUnix=$(TargetsUnix);TestEnabled=$(TestEnabled); + Configuration=$(Configuration);AssemblyFileVersion=$(AssemblyFileVersion);TargetsWindows=$(TargetsWindows);TargetsUnix=$(TargetsUnix); BuildProjectReferences=false;$(ProjectProperties); diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj index 3de9aa3dce..3e7db7d945 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft.Data.SqlClient.csproj @@ -11,7 +11,6 @@ false netcoreapp netstandard - $(DefineConstants);TEST_ENABLED; Debug;Release;netcoreapp2.1-Debug;netcoreapp2.1-Release;netcoreapp3.1-Debug;netcoreapp3.1-Release AnyCPU;x64;x86 $(ObjFolder)$(Configuration).$(Platform)\$(AssemblyName)\netcore\ diff --git a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index cc8fc4cb8d..55c73b99b9 100644 --- a/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netcore/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -136,13 +136,11 @@ public TimeoutState(int value) internal volatile bool _attentionSent; // true if we sent an Attention to the server internal volatile bool _attentionSending; -#if TEST_ENABLED // Below 2 properties are used to enforce timeout delays in code to // reproduce issues related to theadpool starvation and timeout delay. // It should always be set to false by default, and only be enabled during testing. internal bool _enforceTimeoutDelay = false; internal int _enforcedTimeoutDelayInMilliSeconds = 5000; -#endif private readonly LastIOTimer _lastSuccessfulIOTimer; @@ -2291,12 +2289,11 @@ public bool IsTimeoutStateExpired private void OnTimeoutAsync(object state) { -#if TEST_ENABLED if (_enforceTimeoutDelay) { Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); } -#endif + int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; if (timeoutState.IdentityValue == _timeoutIdentityValue) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj index c26373ba1a..cf8c458f2e 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft.Data.SqlClient.csproj @@ -21,7 +21,6 @@ We should remove ResolveComReferenceSilent as soon as we can remove the dependency on mscoree. --> True $(DefineConstants);NETFRAMEWORK; - $(DefineConstants);TEST_ENABLED; $([System.IO.Path]::Combine('$(IntermediateOutputPath)','$(GeneratedSourceFileName)')) diff --git a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs index e8596baab9..0b2baeb0be 100644 --- a/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs +++ b/src/Microsoft.Data.SqlClient/netfx/src/Microsoft/Data/SqlClient/TdsParserStateObject.cs @@ -127,13 +127,11 @@ internal int ObjectID internal bool _attentionReceived = false; // NOTE: Received is not volatile as it is only ever accessed\modified by TryRun its callees (i.e. single threaded access) internal volatile bool _attentionSending = false; -#if TEST_ENABLED // Below 2 properties are used to enforce timeout delays in code to // reproduce issues related to theadpool starvation and timeout delay. // It should always be set to false by default, and only be enabled during testing. internal bool _enforceTimeoutDelay = false; internal int _enforcedTimeoutDelayInMilliSeconds = 5000; -#endif private readonly LastIOTimer _lastSuccessfulIOTimer; @@ -2373,13 +2371,11 @@ public bool IsTimeoutStateExpired private void OnTimeoutAsync(object state) { - -#if TEST_ENABLED if (_enforceTimeoutDelay) { Thread.Sleep(_enforcedTimeoutDelayInMilliSeconds); } -#endif + int currentIdentityValue = _timeoutIdentityValue; TimeoutState timeoutState = (TimeoutState)state; if (timeoutState.IdentityValue == _timeoutIdentityValue) diff --git a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs index 664d528646..0ba98d83b6 100644 --- a/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs +++ b/src/Microsoft.Data.SqlClient/tests/ManualTests/SQL/AsyncTest/AsyncTimeoutTest.cs @@ -92,15 +92,7 @@ private static void RunTest(AsyncAPI api, string commonObj, int timeoutDelay, bo sqlConnection.Open(); if (timeoutDelay != 0) { - try - { - - ConnectionHelper.SetEnforcedTimeout(sqlConnection, true, timeoutDelay); - } - catch - { - Assert.False(true, "Driver does not support explicit timeout delay support. Build all configurations with `/p:TestEnabled=true` property specified."); - } + ConnectionHelper.SetEnforcedTimeout(sqlConnection, true, timeoutDelay); } switch (commonObj) {