Получение ошибки времени ожидания SQL Server с правильными учетными данными, немедленное отклонение с (намеренно) неверными

Question

Это сбивает с толку.Мое приложение ASP.NET 3.5, которое работало нормально, внезапно начало получать ошибки тайм-аута ...

System.Data.SqlClient.SqlException: Истекло время ожидания.Период ожидания истек до завершения операции, или сервер не отвечает

..., но только для запросов с правильным именем пользователя / паролем в строке подключения.Если мы намеренно испортили строку подключения в конфигурации, SQL Server должным образом отклонит запрос, но мгновенно, а не после 15-секундного ожидания (настроенное время ожидания), ясно указав, что у него не было проблем с соединением с сервером.

Мы отскочили окно SQL Server (SQL Server 2005, полностью исправлено) и окно IIS, коснулись web.config, чтобы принудительно перезапустить приложение и т. Д., Но не повезло.Все запросы будут зависать в течение 15 секунд, а затем сообщать об этой ошибке.Мы всегда могли напрямую связаться с сервером базы данных (студия управления, инструменты мониторинга), и я смог сконфигурировать свою локальную копию сайта в Visual Studio так, чтобы она без происшествий попала на тот же сервер базы данных.И эта проблема, возникшая внезапно сама по себе и продолжавшаяся большую часть дня (ошибки начали регистрироваться в 6:17 утра), внезапно разрешилась около 16:30.

Казалось, что она действует, как будто существует сетьпроблема маршрутизации между этим одним веб-сервером и этим одним сервером базы данных, но только с определенным набором учетных данных SQL.Я знаю, что это не имеет никакого смысла, но нет никакого другого сценария, который мы можем себе представить.Я очень опытный разработчик, и ни я, ни наш очень опытный администратор баз данных, ни системные администраторы не могут найти в журналах событий что-либо, что могло бы дать разумное объяснение этому причудливому и самостоятельно разрешаемому набору симптомов.1012 * Это произошло в тестовой среде нашего клиента, которая не была идеальной, но поскольку мы не понимаем, что, черт возьми, произошло, мы обеспокоены тем, что это может внезапно появиться в производстве, и мы будем бить наших коллективных голов по стене,так что любые идеи или дикие теории очень приветствуются.

Генерируемая строка кода, генерируемая LINQ-to-SQL: ExecuteMethodCall:

[Function(Name="dbo.spSetModelingNodeState")]
public int spSetModelingNodeState([Parameter(Name="NodeIdentifier", DbType="VarChar(60)")] string nodeIdentifier, [Parameter(Name="NodeStatus", DbType="Int")] System.Nullable<int> nodeStatus, [Parameter(Name="PoolWeighting", DbType="Float")] System.Nullable<double> poolWeighting)
{
    IExecuteResult result = this.ExecuteMethodCall(this, ((MethodInfo)(MethodInfo.GetCurrentMethod())), nodeIdentifier, nodeStatus, poolWeighting);
    return ((int)(result.ReturnValue));
}

, и мой код, который вызывает этот код,(сокращенно):

using (MyDataContext myDataContext = new MyDataContext(_connectionString))
{
    myDataContext.spSetModelingNodeState(
        Adapter.Identifier, // string
        (int)newHealthValue, // enum, cast to int
        PoolWeighting); // float
}

РЕДАКТИРОВАТЬ: потребовалось несколько дней, чтобы отследить, но я добавил информацию журнала / профилировщика ниже, для каждого запроса комментатора, и тело хранимой процедуры, о которой идет речь

Журналы SQL Server просто показывают входы и выходы из системы, а также отсутствие признаков проблемы.Трассировка Profiler также не имеет пистолета для курения, но следующий кажется , чтобы показать, что заявление занимает 18 секунд.Следуйте spid 82. Он начинается в 4:37:50, делает некоторые вещи, затем spid 83 записывает логин в 4:38:07.Spid 82 записывает свое завершение следующим, с тем же временем начала 4:38:07, но поскольку они регистрируются последовательно, это должно было произойти где-то между 4:38:07 (предыдущий оператор трассировки) и 4:40:10 (следующий).

Spid   Starttime       Event               Query
82     4:37:50 PM      Login               -- network protocol: LPC  set quoted_identifier on  set arithabort off  set numeric_roundabort off  set ansi_warnings on  set ansi_padding on  set ansi_nulls on  set concat_null_yields_null on  set cursor_close_on_commit off  set implicit_transactions off
82     4:37:50 PM      SP:StmtStarting     EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p2
82     4:37:50 PM      SP:Starting         EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p2
82     4:37:50 PM      SP:StmtStarting     UPDATE    ModelingNodeState   SET    NodeStatus = @NodeStatus,    PoolWeighting = ISNULL(@PoolWeighting, PoolWeighting)   WHERE    NodeIdentifier = @NodeIdentifier     
83     4:38:07 PM      Login               -- network protocol: LPC  set quoted_identifier on  set arithabort off  set numeric_roundabort off  set ansi_warnings on  set ansi_padding on  set ansi_nulls on  set concat_null_yields_null on  set cursor_close_on_commit off  set implicit_transactions off
82     4:37:50 PM      SP:Completed        EXEC @RETURN_VALUE = [dbo].[spSetModelingNodeState] @NodeIdentifier = @p0, @NodeStatus = @p1, @PoolWeighting = @p2
80     4:40:10 PM      SP:StmtStarting     SELECT 'Server[@Name=' + quotename(CAST(serverproperty(N'Servername') AS sysname),'''') + ']' + '/Database[@Name=' + quotename(db_name(),'''') + ']' + '/Table[@Name=' + quotename(tbl.name,'''') + ' and @Schema=' + quotename(SCHEMA_NAME(tbl.schema_id),'''') + ']' AS [Urn], tbl.name AS [Name], SCHEMA_NAME(tbl.schema_id) AS [Schema], CAST(   case       when tbl.is_ms_shipped = 1 then 1      when (          select               major_id           from               sys.extended_properties           where               major_id = tbl.object_id and               minor_id = 0 and               class = 1 and               name = N'microsoft_database_tools_support')           is not null then 1      else 0  end                         AS bit) AS [IsSystemObject], tbl.create_date AS [CreateDate], stbl.name AS [Owner] FROM sys.tables AS tbl INNER JOIN sys.database_principals AS stbl ON stbl.principal_id = ISNULL(tbl.principal_id, (OBJECTPROPERTY(tbl.object_id, 'OwnerId'))) WHERE (CAST(   case       when tbl.is_ms_shipped = 1 then 1      when (          select               major_id           from               sys.extended_properties           where               major_id = tbl.object_id and               minor_id = 0 and               class = 1 and               name = N'microsoft_database_tools_support')           is not null then 1      else 0  end                         AS bit)=@_msparam_0) ORDER BY [Schema] ASC,[Name] ASC
80     4:40:10 PM      SQL:BatchStarting   use [master]
62     4:20:10 PM      Logout              NULL
55     4:20:02 PM      Logout              NULL
74     4:13:37 PM      Logout              NULL
59     4:20:10 PM      Logout              NULL
55     4:40:29 PM      Login               -- network protocol: TCP/IP  set quoted_identifier on  set arithabort off  set numeric_roundabort off  set ansi_warnings on  set ansi_padding on  set ansi_nulls on  set concat_null_yields_null on  set cursor_close_on_commit off  set implicit_transactions 
55     4:40:29 PM      SQL:BatchStarting   set transaction isolation level  read committed  set implicit_transactions off 
82     4:37:50 PM      Logout              NULL

Это определенно более глубокий уровень отладки SQL, чем я привык, поэтому, пожалуйста, дайте мне знать, если я неверно читаю это, но, безусловно, кажется, что этот оператор выполнялся безинцидент, просто невероятно медленно.И снова, он работал нормально заранее, запустил тайм-аут, затем возобновил нормальную работу.

Единственное, о чем я могу думать сейчас, когда я публично размышлял, это то, что, если бы было какое-то длительное заклинивание замковдо таблиц, вызываемых sproc, это может объяснить это.Поскольку LINQ-to-SQL в некоторой степени скрывает процесс входа / выхода из системы, вполне возможно, что вход в систему всегда работал нормально, и это всего лишь один вызов sproc, время которого истекло из-за блока.Были ли эти таблицы заблокированы, и если да, то почему, на данный момент невозможно сказать.Похоже ли это на наиболее вероятное объяснение того, что я видел, или у кого-то есть другая теория?

Для полноты вот тело спрока:

/****** Object:  StoredProcedure [dbo].[spSetModelingNodeState]    Script Date: 10/29/2010 14:37:46 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
ALTER PROCEDURE [dbo].[spSetModelingNodeState]
(
@NodeIdentifier varchar(60),
@NodeStatus int,
@PoolWeighting float = NULL
)
AS
/*try to update existing row to new state*/
UPDATE
    ModelingNodeState
SET
    NodeStatus = @NodeStatus,
    PoolWeighting = ISNULL(@PoolWeighting, PoolWeighting)
WHERE
    NodeIdentifier = @NodeIdentifier

IF @@ROWCOUNT = 0
    /*not found, so insert new one*/
    INSERT
        ModelingNodeState(
            NodeIdentifier,
            PoolWeighting,
            NodeStatus,
            LastModelingResult)
    VALUES(
        @NodeIdentifier,
        ISNULL(@PoolWeighting, 1),
        0,
        NULL)

DECLARE @timestamp datetime
SET @timestamp = CURRENT_TIMESTAMP

/*fill endtime of previous node state*/
UPDATE 
    ModelingNodeStateLog
SET
    EndTime = @timestamp
WHERE
    EndTime IS NULL AND
    NodeIdentifier = @NodeIdentifier AND
    NodeStatus <> @NodeStatus

/*start a new entry in the log (yes, I saw I should remove the IF check and always insert, but that's how it currently is in the db)*/
IF @@ROWCOUNT <> 0
    INSERT
        ModelingNodeStateLog
        (
        NodeIdentifier,
        NodeStatus,
        StartTime
        )
    VALUES
        (
        @NodeIdentifier,
        @NodeStatus,
        @timestamp
        )

RETURN

Answer 1

Так как никто не вмешался, я собираюсь предположить, что моя эволюционная теория того, что произошло, была правильной. В частности, это произошло из-за блокировки еще не диагностированного источника в таблице ModelingNodeState или ModelingNodeStateLog, вызвавшего оператор timeout, а не connection timeout. Это различие было скрыто благодаря удобному управлению соединениями в LINQ-to-SQL.

Это согласуется со всеми наблюдаемыми симптомами:

1. Вызовы Sproc с намеренно неверными учетными данными в строке подключения были сразу отклонены на уровне подключения
2. Вызовы Sproc с правильными учетными данными в строке подключения были разрешены для входа (журналы SQL Server показывали нормальный вход / выход из системы), но по истечении времени выполнения оператора снова заблокирована таблица
3. Скрытие LINQ базового управления соединением SQL означало, что трассировка захваченного стека не может использоваться для различения соединения и времени ожидания оператора, и я ошибочно предположил, что это был тайм-аут соединения.
4. Мы понятия не имеем, как / почему / если в одной или обеих таблицах была блокировка на весь день, но нефиксированное утверждение где-то могло бы это сделать, поскольку это началось после ночи развертываний, связанных с работой администратора баз данных, миграцией сценарии и т. д. Это объяснило бы, что вещи начинаются внезапно (после запуска сценария), длятся весь день, а затем внезапно разрешаются, когда нарушающий сценарий фиксируется или откатывается, возможно, когда запущенное приложение закрывается в конце рабочего дня. .

Извлеченные уроки:

1. Не думайте, что вы знаете, что такое вид тайм-аута, это просто потому, что вы видели слово "тайм-аут" в исключении или трассировке стека
2. Размышляя об этом, я понял, что весь этот аспект приложения может полностью потерпеть неудачу без ущерба для критически важных функций приложения. Я собираюсь переписать его, чтобы повторение этой проблемы не повредило целое приложение, как сегодня.

Спасибо за отзывы сообщества, которые подтолкнули меня к (будем надеяться) правильному ответу!

Answer 2

Такое поведение наблюдается после восстановления резервной копии базы данных с другого компьютера.

Это можно исправить с помощью команды SQL в Management Studio. См. Как исправить потерянных пользователей SQL Server