Parameter sniffing в SQL Server 2005/2008 (на примере Project Server 2007)

Столкнулся с интересной ошибкой на загруженном Project Server 2007. Причем проявляется она при активном использовании (читай, в продакте). При разработке, отладке и тестировании данная ошибка не проявилась ни разу. Еще хуже то, что при возникновении ошибки SQL «переклинивает», и без постороннего вмешательства ошибка не исчезает. Ну и под конец — из логов крайне сложно понять причину ее возникновения. Гугл, к сожалению, не помог, что, собственно, и побудило написать об этой проблеме.
Если у вас на странице сведений о проекте «Возникла неожиданная ошибка», а в логе ошибка 7888 (SQL Timeout) — добро пожаловать под кат. Если вы интересуетесь внутренним «эго» SQL Server — тоже стоит почитать.

Анамнез

Ошибка возникает при просмотре сведений о проекте (http://server/pwa/ProjectDrillDown.aspx) в Project Server 2007 Web Access (PWA), и именно при работе с PWA >1 человек (конкретные условия не установлены). Проявлялось на разных Windows Server (2003/2008R2) и на разных SQL Server (2005/2008R2).
На странице отображается:

«Возникла неожиданная ошибка.
Страница обслуживания веб-частей: При наличии соответствующих разрешений вы можете с помощью этой страницы временно закрывать веб-части и удалять личные настройки. За дополнительными сведениями обратитесь к администратору узла.»

(В англоязычной версии: «An unexpected error has occurred. [...]»)

В эвент логе приложений ОС:

Исключение на этапе выполнения. Дополнительные сведения см. ниже.
Сообщение: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
Технические сведения:
System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
at System.Data.SqlClient.SqlDataReader.get_MetaData()
at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
at System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(CommandBehavior behavior)
at System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
at System.Data.Common.DbDataAdapter.Fill(DataSet dataSet)
at Microsoft.Office.Project.Server.DataAccessLayer.DAL.SubDal.FillTypedDataSet(DataSet typedDataSet, String[] tables, SqlCommand sqlCommand)
at Microsoft.Office.Project.Server.DataAccessLayer.DAL.SubDal.FillTypedDataSet(DataSet typedDataSet, String[] tables, String storedProcedureName, SqlParameter[] parameters)
at Microsoft.Office.Project.Server.DataAccessLayer.Generated.ViewDalBase.GetViewReportsByType(Int32 p0, Guid tsUIDprojUID, Guid res_uid)
at Microsoft.Office.Project.Server.BusinessLayer.View.GetViewReportsByType(ViewType viewType, Guid tsUID)
at Microsoft.Office.Project.Server.WebService.PWA.ViewGetViewReportsByType(ViewType viewType, Guid tsUID)

В ULS логе SharePoint (\Program Files\Common Files\Microsoft Shared\Web Server Extensions\12\LOGS\) никакой новой информации по ошибке не было обнаружено. К слову, для чтения логов советую SharePoint ULS Log Viewer.

Итого, что удалось выяснить:
1. Ошибка возникает в файле «ProjectDrillDown.aspx» и раз появившись, сама не лечится.
2. Ошибка возникает при вызове метода ViewGetViewReportsByType и заканчивается SqlException: Timeout expired.
3. Изменение времени таймаута на уровне фермы SharePoint (stsadm -o setproperty -pn database-connection-timeout -pv 60) никакого эффекта не дает.
4. Изменение времени таймаута на уровне инстанса SQL «сбрасывает ошибку», но она очень быстро появляется вновь. В качестве времянки к SQL был прикручен Job, изменяющий параметры инстанса раз в несколько минут.

Обследование

1. Глубокое гугление, ковыряние штатных средств, попытки искусственно воспроизвести ошибку и понять причины ее возникновения не увенчались успехом.
2. Отлавливание SQL Profiler'ом тоже не удалось: на загруженной системе нереальное количество запросов (даже при фильтрации), а на незагруженной — ошибка не проявляется.
3. Пришлось вынуть библиотеку «Microsoft.Office.Project.Server.WebService.PWA.dll» из GAC и распотрошить ее с помощью .Net Reflector. Искомый метод ViewGetViewReportsByType вызывал еще несколько и в итоге я нашел глючащий запрос к SQL. Им оказался запрос (еще через несколько других хранимок) к табличной функции MSP_WEB_FN_SEC_GetAllObjectsResCanViewByViewIDInfo БД ProjectServer_Published.
4. Тут пришлось доставать бубен: UDF написана нормально, никакой инфы в инете по ней нет. Но чудо: вызываешь эту функцию или строишь Execution Plan в SQL Management Studio — и все начинает работать!

Итого: проблема в табличной функции MSP_WEB_FN_SEC_GetAllObjectsResCanViewByViewIDInfo.

Анализ

Я долго не мог понять в чем дело…
А дело было в хитрожопом кэше MSSQL Server и кривых руках написателей вебпарта (зашит в ActiveX) для Project Server 2007.
Дело в том, что при исполнении запросов (в том числе и хранимок) SQL Server создает для них Execution Plan и кладет его в кэш. При следующих запросах они не компилируются, а берутся из кэша (не всегда). В итоге, при каком-то запросе от Project Server (не выяснено при каком) SQL компилировал Execution Plan для функции MSP_WEB_FN_SEC_GetAllObjectsResCanViewByViewIDInfo через жопу, что и вызывало таймаут. И, естественно, пока не сбросишь кэш (изменением параметров БД или рекомпиляцией функции) — Project Server работать не будет.

Лоботомия

Указанная функция внутри содержит курсоры и обращения к пяти часто изменяющимся таблицам, возвращает таблицы разных размеров (в зависимости от входных параметров) и строит запросы с разными Execution Plan. А последний, для нормальной работы данной функции, не должен зависеть от входных параметров (т.н. parameter sniffing). Варианты лечения:
— компиляция функции каждый раз перед запросом;
— закрепление конкретного «правильного» Execution Plan без автообновления;
— отключение parameter sniffing путем переписывания внешних переменных во внутренние.
Первые два варианта годятся только для процедур (через параметр OPTION или WITH), поэтому пациенту были прописаны костыли (третий вариант). Привожу измененную часть функции, добавлены переменные с постфиксом _parameter:

ALTER FUNCTION [dbo].[MSP_WEB_FN_SEC_GetAllObjectsResCanViewByViewIDInfo] (
@res_guid_parameter uniqueidentifier,
@fea_act_uid_parameter uniqueidentifier,
@fAllow_parameter int,
@obj_type_uid_parameter uniqueidentifier,
@view_uid_parameter uniqueidentifier
)
RETURNS @ret_obj_rule_info_tbl table (WSEC_RULE_INFO int, WSEC_CAT_UID uniqueidentifier)
AS
BEGIN
— local variables to disable parameter sniffing
declare @res_guid uniqueidentifier
declare @fea_act_uid uniqueidentifier
declare @fAllow int
declare @obj_type_uid uniqueidentifier
declare @view_uid uniqueidentifier
set @res_guid = @res_guid_parameter
set @fea_act_uid = @fea_act_uid_parameter
set @fAllow = @fAllow_parameter
set @obj_type_uid = @obj_type_uid_parameter
set @view_uid = @view_uid_parameter
[...]

Профилактика

Всем программистам, работающим с SP/UDF, а также всем DBA крайне рекомендую ознакомиться со следующими статьями:
1. Parameter Sniffing & Stored Procedures Execution Plan. Грамотная статья по «parameter sniffing» аж 2006 года, актуальная до сих пор.
2. Batch Compilation, Recompilation, and Plan Caching Issues in SQL Server 2005. Официальное описание внутреннего поведения SQL Server.
3. На хабре была статья с этой проблемой, но почти никто не заинтересовался: MS SQL 2005, Parameter Sniffing, тормозящий Stored Procedure.

PS

Ошибка также проявлялась на платформе с последними SP: WS2008R2/SQL2008R2/MOSS2007SP2/MOPS2007SP2.

UPD 25.02.2011: поправлен текст ошибки.