Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Microsoft SQL Server Новый топик    Ответить
Топик располагается на нескольких страницах: [1] 2   вперед  Ctrl      все
 подтормаживание запроса  [new]
гость04022014
Guest
Доброго времени суток! Пытаюсь разобраться с периодическим подтормаживаением некоторых запросов. Двухзвенка, запросы с параметрами, генерятся приложением при передвижении фокуса в гриде (подтягиваются доп параметры для отображения). Не понятно вот что, снял трассу в случае подвисания. Выполняю в запроснике, с некоей периодичностью наблюдаю это самое подтормаживание, т.е. десять раз выполняется меньше чем за секунду, одиннадцатый раз 10 секунд. Перидичность разная, план запроса абсолютно идентичен. Блокировок нет.

Смотрю счетчики - % Processor Time максимальное 68 %, среднее 5%, в момент подвисания не увеличивается.
Счетчики Logical Disc Avg Disk Read Queue Lenght и Logical Disc Avg Disk Queue Lenght периодически подскакивают до 33 и 39, среднее значение 0.168 и 0.385. Опять таки не вижу динамики при подвисании.
Buffer cache hit ratio среднее 99 %.
Memory PAges/sec Среднее 0.041, максимальное 4.

MS SQL 2008 R2

Подскажите плиз в какую сторону копать, чтоб установить причину подвисания? Какие еще счетчики имеет смысл посмотреть?

P.S. Ситуация конечно не с одним запросом, аналогичная проблема проявляется в разных режимах работы программы.
4 фев 14, 12:42    [15515470]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
Подскажите плиз в какую сторону копать, чтоб установить причину подвисания?

В сторону
- блокировок
- планов выполнения
4 фев 14, 12:44    [15515497]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,
Вот это меня и сбивает. Копирую этот запрос вытащеный профайлером в два окна щелкаю показать актуальный план, выполняю первый - быстро, выполняю несколько раз второй, дожидаюсь пока выполнится долго, сравниваю планы - не вижу отличий. Блокировочник(MS SQL Block) тоже молчит, не краснеет и в логе нет ничего.
4 фев 14, 13:00    [15515656]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
Блокировочник(MS SQL Block) тоже молчит, не краснеет и в логе нет ничего.

А этот "блокировочник" что должен делать при ожидании блокировки ?

гость04022014
сравниваю планы - не вижу отличий.

В плане есть объекты, создаваемые в tempdb ?
4 фев 14, 13:03    [15515696]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,
1. Сторонняя прога, показывает чтото вроде дерева - какие процессы друг друга лочат и время ожидания каждого.

2. Нет, времянок нет в общем он предельно прост, вот (переименовал для удобочитаемости),

--по коду заказа и номенклатуры (класт индекс) выбираются некие параметры,
--к ним джойнится справочник параметров.
exec sp_executesql N'SELECT
ParamNMK.NMKID,
ParamNMK.PARVALUE,
PARNAME.PAR_NAME,
PARNAME.PAR_TYPE
FROM ParamNMK
LEFT JOIN PARNAME ON (ParamNMK.PAR_ID = PARNAME .PAR_ID)
WHERE ParamNMK.NMKID=@P1 and ParamNMK.ORDID=@P2',N'@P1 int,@P2 int'
4 фев 14, 14:02    [15516371]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory
В плане есть объекты, создаваемые в tempdb ?


Т.е. сортировка, группировки, подзапросы? Нет. Но тем не менее три раза вызвал с Duration 2, на четвертый 14.
5 фев 14, 08:16    [15520311]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
alexeyvg
Member

Откуда: Moscow
Сообщений: 31445
гость04022014
Блокировочник(MS SQL Block) тоже молчит, не краснеет и в логе нет ничего
Может, не всё показывает?
Или всё таки в планах есть отличия...

Иначе как объяснить - либо блокировки, либо план...

Скорее всего именно блокировки, поскольку иначе отличались бы и другие показатели - количество чтений, записей, и CPU
5 фев 14, 10:52    [15520878]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
Но тем не менее три раза вызвал с Duration 2, на четвертый 14.

Это абсолютно один и тот же запрос ?
5 фев 14, 11:05    [15520946]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,
Да, те же параметры, даже план запроса один к одному.
5 фев 14, 13:11    [15522101]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
Glory,
Да, те же параметры, даже план запроса один к одному.

А статистика чтений тоже совпадает ?
И STATISTICS TIME ?

Сообщение было отредактировано: 5 фев 14, 13:13
5 фев 14, 13:12    [15522112]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,

Включил отображение Client Statistics, теперь вижу разницу между быстрым и медленным выполнением. Только сходу не понял как ее трактовать.
5 фев 14, 15:40    [15523361]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Быстрое выполнение

К сообщению приложен файл. Размер - 45Kb
5 фев 14, 15:42    [15523376]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
медленное

К сообщению приложен файл. Размер - 77Kb
5 фев 14, 15:43    [15523384]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Ivan Durak
Member

Откуда: Minsk!!!
Сообщений: 3618
не вижу разницы :)

начни с простого - кто в эту таблицу и когда пишет?????
5 фев 14, 17:20    [15524199]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
Glory,

Включил отображение Client Statistics, теперь вижу разницу между быстрым и медленным выполнением. Только сходу не понял как ее трактовать.

Серверные статистики нужны, а не клиентские
5 фев 14, 19:29    [15524808]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
SomewhereSomehow
Member

Откуда: Moscow
Сообщений: 2480
Блог
гость04022014,

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

Если у вас сервер выше 2008 там вроде даже есть соответствующее событие xevent. Но если нет - идея простая, делаете слепок статистики ожиданий до и после запроса.
Примерно так:
if object_id('tempdb..#before') is not null drop table #before;
if object_id('tempdb..#after') is not null drop table #after;
go
select * into #before from sys.dm_os_wait_stats;
go
--Your query here
go
select * into #after from sys.dm_os_wait_stats;
go
select 
	a.wait_type,
	dur = a.wait_time_ms - b.wait_time_ms
from
	#before b
	join #after a on b.wait_type = a.wait_type
order by
	dur desc

И от ожиданий пляшете.
Может быть какие-то блокировки не увидели, может запрос памяти ждет и т.д.

Плохо то, что, к сожалению, на статистику влияет все в данный момент выполняющееся, в отличие от расширенного события. Но тем не менее это даст возможность посмотреть на что обратить внимание.
5 фев 14, 20:16    [15524984]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
SomewhereSomehow,
Спасибо, изучаю ожидания. Там отличий много.
6 фев 14, 13:27    [15528178]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory
гость04022014
Glory,

Включил отображение Client Statistics, теперь вижу разницу между быстрым и медленным выполнением. Только сходу не понял как ее трактовать.

Серверные статистики нужны, а не клиентские


честно говоря сходу не понял где их увидеть. Это в профилере,какието события из раздела Perfomance?
6 фев 14, 13:29    [15528198]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
BOL - SET STATISTICS TIME , SET STATISTICS IO
6 фев 14, 13:30    [15528206]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,

Понятно, это я смотрел вместе с планом. Как трактовать результат не очень понятно,
запрос быстро прошел вижу вот это

SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.
(2 row(s) affected)
SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 26 ms.
SQL Server Execution Times:
CPU time = 31 ms, elapsed time = 51 ms.


запрос подвис на пять секунд, пишет вот что

SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.

(2 row(s) affected)

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
6 фев 14, 16:23    [15529762]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
Glory
Member

Откуда:
Сообщений: 104760
гость04022014
запрос подвис на пять секунд, пишет вот что

SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
SQL Server parse and compile time:
CPU time = 0 ms, elapsed time = 0 ms.

(2 row(s) affected)

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.

Вы уверены, что у вас тормозит запрос, а не передача результатов клиенту ?

Перенаправьте результат вашего select-а во временную таблицу и замерейте время выполнения
6 фев 14, 16:37    [15529880]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
Glory,

Написал Into #temp, все также. Поспотрел несколько статистик ожиданий (запросом, который советовали выше) при долгом выполнении запроса, оставил только те, которые в нормальном варианте нулевые или значительно меньше -

ASYNC_NETWORK_IO 639
LAZYWRITER_SLEEP 5013
REQUEST_FOR_DEADLOCK_SEARCH 5008
BROKER_TO_FLUSH 2067
SLEEP_TASK 27854
PAGEIOLATCH_SH 627

еще (не всегда) появляется
LOGMGR_QUEUE 4978
CXPACKET 396947
7 фев 14, 09:57    [15532605]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
гость04022014
Guest
SELECT TOP 10
 [Wait type] = wait_type,
 [Wait time (s)] = wait_time_ms / 1000,
 [% waiting] = CONVERT(DECIMAL(12,2), wait_time_ms * 100.0 
               / SUM(wait_time_ms) OVER())
  FROM sys.dm_os_wait_stats
  WHERE wait_type NOT LIKE '%SLEEP%' 
  ORDER BY wait_time_ms DESC;


CXPACKET 1907942 53.73
OLEDB 267971 7.55
XE_TIMER_EVENT 126182 3.55
REQUEST_FOR_DEADLOCK_SEARCH 126178 3.55
LOGMGR_QUEUE 126100 3.55
XE_DISPATCHER_WAIT 125491 3.53
FT_IFTS_SCHEDULER_IDLE_WAIT 125123 3.52
CHECKPOINT_QUEUE 121717 3.43
BROKER_EVENTHANDLER 119867 3.38
PAGEIOLATCH_SH 85561 2.41
7 фев 14, 10:04    [15532631]     Ответить | Цитировать Сообщить модератору
 Re: подтормаживание запроса  [new]
SomewhereSomehow
Member

Откуда: Moscow
Сообщений: 2480
Блог
гость04022014,

Запрос с top(10) ожиданий вам не скажет о конкретном узком месте. Лучше смотреть разницу.

И того списка по разнице, что вы привели, некоторые наиболее известные:

  • ASYNC_NETWORK_IO - проблемы с приложением (клиент медленно потребляет данные, например, если в SSMS даже установленной на той же машине что и сервер, выполнить запрос который возвращает много строк - вы увидите такую задержку) либо проблемы с сетью.
  • SLEEP_TASK - общее ожидание используемое в различных случаях, но часто бывает в запросах с операторами Hash Match, когда последние сливают данные на диск
  • PAGEIOLATCH_SH - кратковременная блокировка буфера для IO операции, большие значения могут говорить о проблемах с дисковой подсистемой. На практике может означать, что у вас есть большие сканы, вымывающие страницы из кэша.
  • CXPACKET - ожидание, связанное с обменом данными между параллельными буферами операторов в параллельных планах. Может свидетельствовать о не очень эффективном использовании параллелизма.

    Посмотрите, какие ожидания релевантны вашему случаю?

    К сожалению, хотя в справке и написано:
    BOL: sys.dm_os_wait_stats (Transact-SQL)
    Это агрегированное представление можно использовать для диагностики проблем производительности как всего SQL Server, так и конкретных запросов и пакетов.

    На практике, делать слепки до и после (или как вариант сбрасывать в 0) подходит для изолированного инстанса, либо если можно выделить какие-то промежутки, когда не будет других запросов, в противном случае, будут искажения. Кстати, у вас об этом свидетельствуют и цифры, например если разница CXPACKET до и после 396947 мс, т.е. 5 минут, а ваш запрос самое долгое выполняется 10 секунд, то явно в этот счетчик внесли вклад другие выполнявшиеся в данный момент запросы.

    К счастью, я ошибся с версией, при помощи XEvents можно мониторить ожидания по конкретному SPID даже в версии 2008R2 (в 2008 нужно проверить, наверняка тоже есть). Хотя это не так удобно как в 2012, в основном из-за громоздкости кода и отсутствия нормальной оснастки (есть SSMS Addin, который облегчает жизнь, но до SSMS2012 далеко).

    Пример мониторинга ожиданий при помощи XEvents

    Сначала узнать SPID, в котором будем выполнять запрос
    use master;
    go
    select @@spid -- <- Get To Know SPID
    go
    --select * from spt_values v1, spt_values v2;
    


    В другом окне создаем сессию, я включил два события внутренние ожидания сиквела sqlos.wait_info и внешние sqlos.wait_info_external (когда сервер ждет какое-то внешнее событие выполнение расширенной процедуры, ответ от связанного сервера clr, и т.д.)
    if exists(select * from sys.server_event_sessions where name='QueryWaitStats')
    drop event session QueryWaitStats on server;
    go
    create event session QueryWaitStats on server
    add event sqlos.wait_info (where duration > 1 and [sqlserver].[session_id]=56), -- @@SPID instead of 56
    add event sqlos.wait_info_external (where duration > 1 and [sqlserver].[session_id]=56) -- @@SPID instead of 56
    add target package0.ring_buffer
    with (
    	event_retention_mode = allow_single_event_loss, 
    	max_dispatch_latency = 5 seconds
    )
    


    Вместо 56 (ид в моем эксперименте) поставьте свой ИД. Кроме того, можете регулировать какие по длительности ожидания включать, я поставил выше 1 мс (duration > 1). Кроме того, местом, куда будут сыпаться события, я выбрал ring_buffer, если событий много или надолго, то лучше выбирать файл (asynchronous_file_target).

    Стартуем сессию
    alter event session QueryWaitStats on server state = start;
    go
    


    В первом окне выполняем интересующий нас запрос, например:
    select * from spt_values v1, spt_values v2;
    


    Далее смотрим результаты (уродливый запросец):
    +
    with RingBufferData as
    (
        select 
    		TargetData = cast(target_data as xml)
        from 
    		sys.dm_xe_session_targets st 
    		JOIN sys.dm_xe_sessions s ON s.address = st.event_session_address 
        where name = 'QueryWaitStats' AND target_name = 'ring_buffer'
    ),
    Data as
    (
        select 
    		[EventData] = XEventData.XEvent.query('.') 
        from 
    		RingBufferData rbd
    		cross apply rbd.TargetData.nodes ('RingBufferTarget/event') AS XEventData (XEvent)
    ),
    Waits as (
    select 
        [Event] = [EventData].value('(event/@name)[1]', 'varchar(50)'),
        [Timestamp] = DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), [EventData].value('(event/@timestamp)[1]', 'datetime2')),
        [WaitType] = [EventData].value('(event/data[@name="wait_type"]/text)[1]', 'nvarchar(4000)'),
        [Dur] = [EventData].value('(event/data[@name="duration"]/value)[1]', 'bigint')
    from 
    	Data
    )
    select 
    	[Event],
    	[WaitType],
    	[MinTimestamp] = min([Timestamp]),
    	[MaxTimestamp] = max([Timestamp]),
    	[Dur] = sum([Dur])
    from
    	Waits
    group by
    	[Event],
    	[WaitType]
    order by
    	[Dur] desc
    go
    


    Останавливаем сессию:
    alter event session QueryWaitStats on server state = stop;
    go
    


    В результате получилась такая картина:
    Картинка с другого сайта.
    Нас интересует ожидание NETWORK_IO, оно соответствует ожиданию ASYNC_NETWORK_IO (большинство названий полностью совпадает dm_os_wait_stats).
    Т.е. этот как раз тот случай, про который я говорил вначале, даже будучи установленными локально SSMS и SQLServer, SSMS не успевает получать данные от сервера (мы выбрали кросс дойном очень много строк) и сервер ждет клиента.

    Похожим образом можете посмотреть, чего ждет ваш запрос.

    Можно просто посмотреть чего ждет запрос, также по SPID при помощи представлений:
    select er.wait_time, er.last_wait_type, * from sys.dm_exec_requests er
    или
    select * from sys.dm_os_waiting_tasks

    П.С.
    Вообще странная ситуация, статистика set statistics time, по-идее включает в себя и время передачи клиенту, почему у вас везде по нулям. Дело точно в сервере?
  • 7 фев 14, 13:04    [15533983]     Ответить | Цитировать Сообщить модератору
     Re: подтормаживание запроса  [new]
    гость04022014
    Guest
    SomewhereSomehow,
    Спасибо за ответ. Я залогинился на ноде на которой в данный момент запущен сервер. Попытался позапускать запрос прямо там, мне за несколько десятков запусков не удалось получить задержку. Удаленно подвисает через каждые 5 - 10 запусков. В общем похоже не совсем в сервере дело?
    7 фев 14, 15:37    [15535313]     Ответить | Цитировать Сообщить модератору
    Топик располагается на нескольких страницах: [1] 2   вперед  Ctrl      все
    Все форумы / Microsoft SQL Server Ответить