Необходимость трассировки возникла после жалоб пользователей одного из офисов нашей компании на «внезапно появляющиеся» и столь же «внезапно исчезающие тормоза». Были исследованы планы предположительно «тормозящих» запросов, блокировки, счетчики сервера, канал связи, но явных проблем нигде не обнаружилось. По этому возникла резонная мысль посмотреть, а что происходит на сервере в этот момент, и главное когда именно (точное время) этот момент наступает и когда заканчивается. Для этих целей как раз и используется трассировка.
В данной заметке мы рассмотрим какие недостатки есть у стандартной утилиты Profiler, почему она непригодна для долгосрочного мониторинга, как выполнять трассировку не используя Profiler, а также как обрабатывать и анализировать полученные результаты.
Почему для долгосрочной трассировки не подходит Profiler
Самая очевидная и первая мысль — использовать для трассировки SQL Server Profiler, к тому же Profiler умеет писать трассу сразу в таблицу, что может быть удобным для последующего анализа. Profiler — отличная утилита и лично я, пользуюсь им постоянно для разных нужд, но в основном это оперативные нужды, ненадолго открыть, что-то посмотреть и закрыть. Но в данном случае такой подход не очень подходил, т.к. трассу нужно снимать постоянно, и держать у себя на машине постоянно открытый работающий Profiler — не очень хорошо.
Вот что по этому поводу пишет Кен Хендерсон в своей книге «Профессиональное руководство по SQL Server хранимые процедуры, XML»:
Все это касается 2000 сервера и утилиты Sql Profiler 8.0. Мне стало интересно, как обстоят дела в SQL Server Profiler 10.0 и как он осуществляет запись в таблицу. Для исследование профайлера возьмем…профайлер =). Точнее два профайлера, первый будет регистрировать действия второго, второй — будет писать в таблицу.
В качестве сервера для теста, я использую sql server express на своей машине, версии
Microsoft SQL Server 2005 — 9.00.3042.00 (Intel X86) Feb 9 2007 22:47:07 Copyright (c) 1988-2005 Microsoft Corporation Express Edition on Windows NT 5.1 (Build 2600: Service Pack 3)
Обычно в боевых условиях профайлер запускается на локальной машине и по сети соединяется с сервером, по этому для чистоты эксперимента (чтобы взаимодействие осуществлялось посредством TCP а не посредством Shared memory), подключимся к своему локальному серверу по ip адресу. Если требуется, необходимо предварительно включить протокол TCP в Configuration Manager, который по умолчанию отключен для Express Edition.
Текущие соединения, впринципе, можно мониторить при помощи того же профайлера, но я решил, что буду смотреть соединения в Sql Server Management Studio (SSMS), при помощи exec sp_who2.
Пока все, что мы там видим, это:
|
Т.е. подключена только сама SSMS (есть еще внутренние подключения но я их опустил, чтобы не загромождать пост уж совсем окончательно =) ).
Итак, запускаем первый профайлер.
В открывшемся окне свойства трассировки, переходим на вкладку Events Selection. В событиях трассировки, выбираем события RPC:Completed и SQL: BatchComplited. Выберем колонки TextData, ApplicationName, SPID.
Далее кнопка Column FIlter, фильтр ApplicationName. Скопируем оттуда из атрибута Not Like значение, это название текущего инстанса профайлера.
У меня это SQL Server Profiler — c54ef85b-2631-4592-bd25-3eaf856cb1a9.
Посмотрим, что сейчас вернет exec sp_who2.
|
Видим, что теперь у сервера есть еще одно подключение, от профайлера c54ef85b-2631-4592-bd25-3eaf856cb1a9, как и ожидалось.
Запускаем трассировку.
Теперь запустим второй профайлер. Выберем событие SQL:BatchComplited, с такими же колонками TextData, ApplicationName, SPID. Из фильтров копируем значение инстанса этого профайлера, у меня это SQL Server Profiler — f954baed-324c-4352-9b7f-7e6869f0518e.
В тот же фильтр добавим значение SQL Server Profiler — c54ef85b-2631-4592-bd25-3eaf856cb1a9 (чтобы этот профайлер не логировал первый).
Посмотрим текущие подключения:
|
Все ок, у нас появилось еще одно соединение, на этот раз с профайлером f954baed-324c-4352-9b7f-7e6869f0518e.
А теперь, вернемся на вкладку General и поставим галочку Save to table. Видим, что профайлер запросил параметры для еще одного подключения.
Подключимся и выберем базу и таблицу (если ее нет, она будет создана), в которую будет писаться трасса. У меня это [Test1].[dbo].[tracelog].
Запустим трассировку и посмотрим что с подключениями.
|
Мы видим, что есть два подключения, от одного и того же инстанса профайлера SQL Server Profiler — f954baed-324c-4352-9b7f-7e6869f0518e.
Ту же картину, можно наблюдать внешней утилитой TCPView (можно бесплатно скачать с сайта sysinternals.com).
Видно что профайлер с ид процесса 1232 — имеет одно соединение, а с ид процесса 6220 — два.
Итак, дополнительное соединение все же открывается. Я не вижу в этом ничего криминального, просто такой факт наличествует, профайлер открывает соединение для записи в таблицу.
Посмотрим, что в нем происходит, для этого, обратимся к первому профайлеру (c54ef85b-2631-4592-bd25-3eaf856cb1a9), на котором у нас все это время работала трассировка, и посмотрим, что он зафиксировал.
Вот что мы видим.
declare @p1 int set @p1=3 exec sp_trace_create @p1 output,1,NULL,NULL,NULL select @p1 go exec sp_trace_setevent 3,12,1,1 go exec sp_trace_setevent 3,12,10,1 go exec sp_trace_setevent 3,12,12,1 go exec sp_trace_setfilter 3,10,0,7,N'SQL Server Profiler - f954baed-324c-4352-9b7f-7e6869f0518e' go exec sp_trace_setfilter 3,10,0,7,N'SQL Server Profiler - c54ef85b-2631-4592-bd25-3eaf856cb1a9' go exec sp_trace_setstatus 3,1 go select * from [dbo].[tracelog] go DROP TABLE [dbo].[tracelog] go CREATE TABLE [dbo].[tracelog] ([RowNumber] int IDENTITY(0,1) PRIMARY KEY, [EventClass] int NULL,[TextData] ntext NULL,[ApplicationName] nvarchar(128) NULL,[SPID] int NULL,[BinaryData] image NULL) go declare @p1 int set @p1=180150003 declare @p3 int set @p3=2 declare @p4 int set @p4=4 declare @p5 int set @p5=-1 exec sp_cursoropen @p1 output,N'select * from [dbo].[tracelog]',@p3 output,@p4 output,@p5 output select @p1, @p3, @p4, @p5 go exec sp_cursor 180150003,4,0,N'[dbo].[tracelog]',@EventClass=65528,@TextData=NULL,@ApplicationName=NULL,@SPID=NULL,@BinaryData=0xFFFE...00 go exec sp_cursor 180150003,4,0,N'[dbo].[tracelog]',@EventClass=65534,@TextData=NULL,@ApplicationName=NULL,@SPID=NULL,@BinaryData=NULL go
То есть, мы видим, что профайлер, в одном соединении (spid 54) создает трассировку, устанавливает ее параметры, фильтры и т.д. В другом соединении (spid 55) создает таблицу, открывает курсор, и осуществляет запись, полученной трассировочной информации в таблицу посредством курсора.
Конечно, и в этом нет ничего криминального (хотя когда я слышу «курсор», применительно к sql server, мне становится как то неуютно =) ).
Подведем итог.
Скажу сразу я лично, не был свидетелем того как профайлер при длительной работе «подвесил» бы sql server и таких экспериментов не ставил.
Но факты:
- постоянно открытое дополнительное соединение
- Накладные расходы на передачу данных. схема при которой данные передаются по сети сначала на машину с профайлером, тут записываются в параметры для вызова sp_cursor, и собственно передаются обратно на сервер для записи.
- Постоянно открытый курсор, через который осуществляется запись.
- Постоянно висящий открытый профайлер, в котором, к тому же идет он-лайн отображение того, что происходит на сервере, и вывод всех строк на экран (что тоже требует ресурсов локальной машины).
- Предостережения умных людей =)
— заставляют отказаться от использования схемы Profiler Таблица для долгосрочного мониторинга и логирования действий.
К тому же есть замечательная альтернатива в виде процедур семейства sp_trace.
Процедуры sp_trace
Хранимые процедуры, которые начинаются с префикса sp_trace, служат в sql server-е для управления трассировкой. Они вовсе не такие сложные как может показаться на первый взгляд. Кстати, тот же самый профайлер, для создания трассировки, использует эти же функции. Мы это уже видели в предыдущем листинге.
Подробно и академически описывать каждую не имеет смысла, т.к. они все хорошо описаны в документации, по этому я их только перечислю и дам краткое описание, после этого сразу перейдем к практике.
sp_trace_create — создает трассировку (после создания трассировка находится в приостановленном состоянии).
sp_trace_setevent — устанавливает события и колонки, по которым ведется трассировка.
sp_trace_setstatus — устанавливает статус трассировки (0 — Останавливает указанную трассировку, 1 — Начинает указанную трассировку, 2 — Закрывает указанную трассировку и удаляет ее определение из сервера)
fn_trace_getinfo — получает в зависимости от параметров сведения об одной или всех трассировках.
fn_trace_gettable — получает непосредственно сами данные трассировки, из трассировочного файла.
Некоторые полезные представления, которые появились с 2005 версией:
sys.traces — выводит все текущие запущенные трассировки, используется для замены fn_trace_getinfo.
sys.trace_categories — выводит категории событий.
sys.trace_events — выводит события трассировки, в привязке к категории.
sys.trace_columns — выводит информацию о колонках трассировки, их название, размер тип.
Стратегия использования.
Параметры создания трассировки.
Создавая трассировку, вы можете указывать максимальный размер файла трассировки (по умолчанию 5 Мб), количество файлов трассировки (должно быть больше 1), и различные опции трассировки.
В их числе опция TRACE_FILE_ROLLOVER, она определяет будет ли создаваться новый файл трассировки, в том случае если размер файла достигнет значения, определенного параметром «максимальный размер файла».
Более подробно об этом можно почитать в документации. То, что наиболее важно для нас, это возможность варьировать параметры максимальный размер файла и кол-во файлов, при заданной опции TRACE_FILE_ROLLOVER.
Что это дает, объясню на примере.
Например, мы задаем имя файла трассировки MYTRACE.trc, устанавливаем опцию TRACE_FILE_ROLLOVER, задаем кол-во файлов равное 10, максимальный размер 1 мб. Это значит, что будет создан файл MYTRACE.trc, в него будут записываться данные трассировки, когда файл достигнет 1 Мб, будет создан новый файл, который получит название MYTRACE_1.trc (название файлов сервер формирует автоматически), после его заполнения, создастся новый файл MYTRACE_2.trc и т.д. до тех пор пока кол-во файлов не станет равным 10 (т.е. равным тому кол-ву, которое мы задали параметром «кол-во файлов»). Что произойдет после этого? после этого, самый старый файл MYTRACE.trc удалится, и вместо него будет создан новый файл MYTRACE_10.trc, потом удалится файл MYTRACE_1.trc, вместо него запишется файл MYTRACE_11.trc и т.д. по циклу, сервер удаляет старые файлы, замещая их новыми, увеличивая счетчик названий.
Возникает резонный вопрос, зачем эта возня с файлами, почему бы не писать все в один большой файл. Дело в том что в функции получения информации из файла, можно указывать начальный файл, и кол-во файлов, которое мы желаем прочитать. Если у нас будет один большой файл, то, чтобы получить последние изменения, каждый раз придется читать его целиком, что со временем будет приводить все к бОльшим потерям времени.
Как выбирать критерии размер/количество файлов? Каждый выбирает исходя из своих нужд, по принципу насколько быстро у него заполняются файлы и с какой глубиной он хочет хранить историю. Быстрота заполнения файлов зависит от количества выбранных событий (насколько подробны вы делаете трассировку), интенсивности возникновения этих событий на сервере (нагрузки на сервер). Я для себя эмпирически определил, что в часы пик высокой нагрузки 5 мб заполняются примерно за 30 минут, в часы простоя около 2 часов. В среднем в день на этом сервере заполняется примерно 10 файлов. Количество дней, которое я хочу хранить в истории примерно 2 дня. Т.е. образуется окно в 20 файлов.
Вот код процедуры, которая могла бы запускать подобную трассировку.
Посмотреть запущенные трассировки можно сделав запрос к представлению sys.traces.
Кстати, в списке активных трассировок вы можете увидеть трассировку с примерно таким файлом «C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\LOG\log_74.trc». Это трассировка по-умолчанию, которую ведет сервер в помощь dba для поиска и устранения неисправностей. Управлять ее включением и отключением можно при помощи параметра default trace enabled.
Загрузка в таблицу.
Трассировочные файлы это конечно хорошо, к их содержимому можно получить доступ функцией fn_trace_gettable, но хотелось бы иметь данные сразу в табличном виде.
Для этого я:
— создал таблицу в которой будут храниться данные трассировки;
— создал таблицу логирования фактов загрузки файлов трассировки в таблицу;
— написал относительно простую процедуру, которая загружает данные в таблицу из файла;
— зарядил эту процедуру в job по расписанию.
Процедура выполняет следующие действия. Получает имя текущего загружаемого файла, получает из таблицы предыдущих загрузок имя предыдущего загруженного файла, вычленяет из каждого номера, берет их разницу, и если таковая есть — формирует название файла, который необходимо загрузить и отдает его в функцию fn_trace_gettable, при помощи которой происходит загрузка.
Идея процедуры понятна, код тоже не сложный. Привожу его набросок.
Частота срабатывания job-а может быть любой, разумно, наверное сделать ее такой, при которой процедура бы загружала 1-2 файла за раз. У меня это примерно раз в час. Еще можно создать второй джоб, в котором производить очистку данных в таблице, т.е. глубиной истории теперь можно управлять непосредственно там, удаляя ненужные старые данные.
На этом собственно все.
В завершении скажу, что проблема, из-за которой появлялись тормоза, оказалась в том, что при мониторинге пропустили один из счетчиков, потом прослеживая по трассе моменты просадки сервера и сопоставляя их с данными счетчиков, удалось выяснить причину. Ей оказалась нехватка оперативной памяти при определенном стечении обстоятельств.
Сейчас когда проблема решена, трассировка тоже работает, ловит долго выполняющиеся запросы, и скидывает их в отдельную таблицу, куда всегда можно заглянуть в поисках горячей десятки «Топ-10 тормознутых запросов» и позаниматься на досуге их оптимизацией =).
Надеюсь, кому-нибудь мой опыт окажется полезным.