Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Microsoft SQL Server Новый топик    Ответить
 Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
Привет всем!
Версия сервера :

Microsoft SQL Server 2012 (SP3-CU8) (KB4013104) - 11.0.6594.0 (X64)   Mar 15 2017 10:52:31   Copyright (c) Microsoft Corporation  Enterprise Edition (64-bit) on Windows NT 6.3 <X64> (Build 14393: ) (Hypervisor) 


Есть процедура "A", которая выполняет 3 запроса:
1) выборку целочисленного поля во временную таблицу ( и небольшого числа строк из таблицы "B" размером в 40k)
(подозрений к запросу нет)
2) обновление целочисленного поля во временной таблице в джойне с таблицей "B"
(подозрений к запросу также нет)
3) запрос с несколькими джойнами и вызовами пользовательских функций, который вероятно страдает от блокировок.

Есть трасса, в которую пишется длительность выполнения процедуры "A"

Примеры из трассы...

+
SPIDProc"Duration_mcs"ReadsWrites"CPU_ms"StartTimeEndTimeTextData
143A22073138229501882019-06-23 3:18:152019-06-23 3:18:15"exec dbo.[A] @pids=default@pid=42525@delimiter=default@uid='1906230312cgq0cxpkn7'@defaultProducts=0@cid=default@skus=default"
178A22095638229102032019-06-23 0:43:222019-06-23 0:43:23"exec dbo.[A] @pids=default@pid=46168@delimiter=default@uid='1906231231xyfe8jpixt'@defaultProducts=0@cid=default@skus=default"
124A22104038229502032019-06-23 2:47:532019-06-23 2:47:53"exec dbo.[A] @pids=default@pid=19913@delimiter=default@uid='1906230247xez69pg0x0'@defaultProducts=0@cid=default@skus=default"
85A22104138229501882019-06-23 2:54:172019-06-23 2:54:17"exec dbo.[A] @pids=default@pid=32752@delimiter=default@uid='190614021295y4kdhi9k'@defaultProducts=0@cid=default@skus=default"
60A22123938229101882019-06-23 1:50:412019-06-23 1:50:41"exec dbo.[A] @pids=default@pid=51274@delimiter=default@uid='1906230149h0m920gtzu'@defaultProducts=0@cid=default@skus=default"
155A22126438229401882019-06-23 0:05:022019-06-23 0:05:02"exec dbo.[A] @pids=default@pid=42901@delimiter=default@uid='1906231200uki8jsvto8'@defaultProducts=0@cid=default@skus=default"
186A22141638233301872019-06-23 1:34:342019-06-23 1:34:34"exec dbo.[A] @pids='450555672044830'@pid=default@delimiter=default@uid='1906231200hy35wl9mwl'@defaultProducts=0@cid=default@skus=default"
155A22146138229802192019-06-23 0:59:232019-06-23 0:59:23"exec dbo.[A] @pids=default@pid=45098@delimiter=default@uid='1906111049ocsiftmtbq'@defaultProducts=0@cid=default@skus=default"
177A22174238229102182019-06-23 0:28:242019-06-23 0:28:24"exec dbo.[A] @pids=default@pid=42797@delimiter=default@uid='19061109158iwv0ux7dv'@defaultProducts=0@cid=default@skus=default"
154A22174338228902182019-06-23 2:08:552019-06-23 2:08:56"exec dbo.[A] @pids=default@pid=45881@delimiter=default@uid='1906230207wdymbg2656'@defaultProducts=0@cid=default@skus=default"
128A22175638238302032019-06-23 3:29:062019-06-23 3:29:06"exec dbo.[A] @pids=default@pid=58079@delimiter=default@uid='1906230253jo21h57762'@defaultProducts=0@cid=default@skus=default"
324A22181338229502032019-06-23 2:58:462019-06-23 2:58:46"exec dbo.[A] @pids=default@pid=53177@delimiter=default@uid='1906230210gvbxaww8n2'@defaultProducts=0@cid=default@skus=default"
188A22185038229501882019-06-23 1:46:132019-06-23 1:46:14"exec dbo.[A] @pids=default@pid=40255@delimiter=default@uid='1906230142zbi3zwnjem'@defaultProducts=0@cid=default@skus=default"
128A22188638229502032019-06-23 3:29:052019-06-23 3:29:06"exec dbo.[A] @pids=default@pid=51325@delimiter=default@uid='1906230328x0b7d1rskz'@defaultProducts=0@cid=default@skus=default"
178A22191538228802032019-06-23 0:35:472019-06-23 0:35:48"exec dbo.[A] @pids=default@pid=44828@delimiter=default@uid='1906231235lchtjii2l4'@defaultProducts=0@cid=default@skus=default"
154A22193038229102032019-06-23 2:27:352019-06-23 2:27:35"exec dbo.[A] @pids=default@pid=42513@delimiter=default@uid='1906230226vmx0etx8hb'@defaultProducts=0@cid=default@skus=default"
154A22195138229001872019-06-23 2:37:002019-06-23 2:37:00"exec dbo.[A] @pids=default@pid=45803@delimiter=default@uid='1906230221u0e83v9p5v'@defaultProducts=0@cid=default@skus=default"
128A22200938228902192019-06-23 3:27:392019-06-23 3:27:39"exec dbo.[A] @pids=default@pid=52758@delimiter=default@uid='1906231226w5bdlylhe2'@defaultProducts=0@cid=default@skus=default"
124A22205138228902032019-06-23 0:44:522019-06-23 0:44:53"exec dbo.[A] @pids=default@pid=46103@delimiter=default@uid='19061112471jovtm9rh1'@defaultProducts=0@cid=default@skus=default"
154A22206138229001872019-06-23 2:48:052019-06-23 2:48:05"exec dbo.[A] @pids=default@pid=53630@delimiter=default@uid='1906230234ra5mu2tpk4'@defaultProducts=0@cid=default@skus=default"
175A3121043724452701252019-06-23 1:31:042019-06-23 1:31:35"exec dbo.[A] @pids='5127143994'@pid=default@delimiter=default@uid='1906230130njok07q0xy'@defaultProducts=0@cid=default@skus=default"
71A3117155622286001252019-06-23 1:31:062019-06-23 1:31:37"exec dbo.[A] @pids='429064634446108545864290646344531764610352560579665317646103526585290357558579675265852903'@pid=default@delimiter=default@uid='1906220941rqbhonjly2'@defaultProducts=0@cid=default@skus=defa"
146A3103231428235201722019-06-23 1:30:562019-06-23 1:31:27"exec dbo.[A] @pids='4355543327'@pid=default@delimiter=default@uid='1906231254r3ragw67z5'@defaultProducts=0@cid=default@skus=default"
132A3101762222265201882019-06-23 1:30:582019-06-23 1:31:29"exec dbo.[A] @pids=default@pid=19913@delimiter=default@uid='1906230117nc030xy4xa'@defaultProducts=0@cid=default@skus=default"
154A3048170822265501722019-06-23 1:30:502019-06-23 1:31:21"exec dbo.[A] @pids=default@pid=28274@delimiter=default@uid='1906230130hnizasqotc'@defaultProducts=0@cid=default@skus=default"
165A3046287225773201562019-06-23 1:30:582019-06-23 1:31:29"exec dbo.[A] @pids='5205454586'@pid=default@delimiter=default@uid='1906230130dnr5fmdj4i'@defaultProducts=0@cid=default@skus=default"
172A3035931822265001412019-06-23 1:31:022019-06-23 1:31:32"exec dbo.[A] @pids=default@pid=54594@delimiter=default@uid='1906230130nb2rkid34q'@defaultProducts=0@cid=default@skus=default"
318A3031377922264901882019-06-23 1:30:522019-06-23 1:31:22"exec dbo.[A] @pids=default@pid=51277@delimiter=default@uid='1906230129pcd18l1c31'@defaultProducts=0@cid=default@skus=default"
320A3014368222271701562019-06-23 1:30:592019-06-23 1:31:29"exec dbo.[A] @pids='45076427014507642701'@pid=default@delimiter=default@uid='1906230130yivgh5gkqx'@defaultProducts=0@cid=default@skus=default"
160A2716139638229202812019-06-23 1:10:272019-06-23 1:10:55"exec dbo.[A] @pids=default@pid=46276@delimiter=default@uid='1906230101vvvvm3gvh9'@defaultProducts=0@cid=default@skus=default"
154A2640514738228902662019-06-23 1:10:282019-06-23 1:10:55"exec dbo.[A] @pids=default@pid=45101@delimiter=default@uid='1906231216iyeryn02q9'@defaultProducts=0@cid=default@skus=default"
178A2633140038240902192019-06-23 1:10:262019-06-23 1:10:52"exec dbo.[A] @pids=default@pid=42482@delimiter=default@uid='19062312528qqfk2ggf4'@defaultProducts=0@cid=default@skus=default"
178A2504748538263502502019-06-23 1:31:182019-06-23 1:31:43"exec dbo.[A] @pids='429064634446108545864290646344531764610352560579665317646103526585290357558579675265852903'@pid=default@delimiter=default@uid='1906230129r7j8euaa8p'@defaultProducts=0@cid=default@skus=defa"
152A2452674738229101882019-06-23 1:10:322019-06-23 1:10:57"exec dbo.[A] @pids=default@pid=52658@delimiter=default@uid='190623010429npk750nm'@defaultProducts=0@cid=default@skus=default"
146A2448620938229102342019-06-23 1:10:342019-06-23 1:10:59"exec dbo.[A] @pids=default@pid=45060@delimiter=default@uid='1906111049ocsiftmtbq'@defaultProducts=0@cid=default@skus=default"
122A2412377538229502182019-06-23 1:10:272019-06-23 1:10:51"exec dbo.[A] @pids=default@pid=45164@delimiter=default@uid='1906230109b5i7qsdqtl'@defaultProducts=0@cid=default@skus=default"
128A2235838238228902972019-06-23 1:31:202019-06-23 1:31:43"exec dbo.[A] @pids=default@pid=44828@delimiter=default@uid='1906230131xjc34gyyqv'@defaultProducts=0@cid=default@skus=default"
143A2178787338230602812019-06-23 1:10:372019-06-23 1:10:59"exec dbo.[A] @pids=default@pid=56335@delimiter=default@uid='1906220630ik2zwnza5t'@defaultProducts=0@cid=default@skus=default"
170A2173989638236402972019-06-23 1:31:212019-06-23 1:31:43"exec dbo.[A] @pids='44823449324482344932'@pid=default@delimiter=default@uid='1906230131qvr7u372mj'@defaultProducts=0@cid=default@skus=default"
341A2160196838238102502019-06-23 0:17:232019-06-23 0:17:45"exec dbo.[A] @pids=default@pid=44914@delimiter=default@uid='1906221137u0jcy87dgq'@defaultProducts=0@cid=default@skus=default"


Мои имно-выводы по трассе: раз запрос сравнительно одинаковое время утилизирует CPU, а Duration взлетает от 220ms до 30 секунд, значит в тяжелых случаях запрос страдает от блокировок...

Вопросы:
1) как можно узнать какие задержки приводят к увеличению Duration запроса?
2) можно ли это "узнать" на уровне трассы?

Сообщение было отредактировано: 26 июн 19, 14:16
24 июн 19, 18:50    [21914351]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
Владислав Колосов
Member

Откуда:
Сообщений: 7762
1klassNick,

явно не хватает каких-то индексов, т.к. количество чтений приблизительно одинаково для каждого выполнения. Что наводит на мысль о просмотре данных вместо поиска.
24 июн 19, 19:01    [21914355]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
komrad
Member

Откуда:
Сообщений: 5244
1klassNick,

у вас 30-секундные вызовы отличаются от быстрых - покажите их картинкой, а то текстовое разбиение на столбцы выглядит неочевидно

быстрый
2019-06-23 2:48:05	2019-06-23 2:48:05	"exec dbo.[A] @pids=default	@pid=53630	@delimiter=default	@uid='1906230234ra5mu2tpk4'	@defaultProducts=0	@cid=default	@skus=default"


медленный
2019-06-23 1:30:59	2019-06-23 1:31:29	"exec dbo.[A] @pids='45076	42701	45076	42701'	@pid=default	@delimiter=default	@uid='1906230130yivgh5gkqx'	@defaultProducts=0	@cid=default	@skus=default"
24 июн 19, 19:08    [21914361]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
komrad
1klassNick,

у вас 30-секундные вызовы отличаются от быстрых - покажите их картинкой, а то текстовое разбиение на столбцы выглядит неочевидно

быстрый
2019-06-23 2:48:05	2019-06-23 2:48:05	"exec dbo.[A] @pids=default	@pid=53630	@delimiter=default	@uid='1906230234ra5mu2tpk4'	@defaultProducts=0	@cid=default	@skus=default"


медленный
2019-06-23 1:30:59	2019-06-23 1:31:29	"exec dbo.[A] @pids='45076	42701	45076	42701'	@pid=default	@delimiter=default	@uid='1906230130yivgh5gkqx'	@defaultProducts=0	@cid=default	@skus=default"



запросы с параметрами выбраны из реальной трассы (имя хп лишь заменил на "A")

в выбранном куске есть очень похожие структурно вызовы:

--быстрый
exec dbo.[A] @pids=default,@pid=19913,@delimiter=default,@uid='1906230247xez69pg0x0',@defaultProducts=0,@cid=default,@skus=default


и

--медленный
exec dbo.[A] @pids=default,@pid=19913,@delimiter=default,@uid='1906230117nc030xy4xa',@defaultProducts=0,@cid=default,@skus=default



Перед тем как оптимизировать запрос хотелось бы выяснить от чего он страдает.
И почему такая разница при одинаковых IO и CPU.


Если посмотреть текущий план из кэша, то запрос имеет две статистики

creation_timelast_execution_timeAvgCPUTime_msAvgTimeBlocked_msAvgIOexecution_countplan_generation_numtotal_worker_time_mstotal_time_blocked_msLogicalReadslogicalWritesAggIO
2019-06-23 10:42:372019-06-24 12:43:36211.539262884.89556888382313.595558359512345219.844954420.5042231143901610222311439118
2019-06-15 23:10:012019-06-24 10:12:29286.89457141052.002397382071.714363818074.35866276.15124070518024070518



для второй статистики средняя задержка высокая, но в пределах секунды...
24 июн 19, 19:55    [21914385]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
invm
Member

Откуда: Москва
Сообщений: 9349
1klassNick,

Ожидания имеют место в строках, где Duration значительно больше CPU. Кстати, почему они у вас в разных единицах измерения?

Чтобы отловить подробности ожиданий настрпойте сессию Extended Events с событиями Module start, Module end, Wait_info с соответствующими фильтрами.
24 июн 19, 20:22    [21914394]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
invm
1klassNick,

Ожидания имеют место в строках, где Duration значительно больше CPU. Кстати, почему они у вас в разных единицах измерения?

Чтобы отловить подробности ожиданий настрпойте сессию Extended Events с событиями Module start, Module end, Wait_info с соответствующими фильтрами.


тут описано в каких единицах представлены поля в трассе

BOL

К сообщению приложен файл. Размер - 45Kb
24 июн 19, 20:48    [21914403]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
invm
Member

Откуда: Москва
Сообщений: 9349
1klassNick
тут описано в каких единицах представлены поля в трассе
И что мешает привести их в запросе к одной единице?
24 июн 19, 21:04    [21914404]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
invm
1klassNick,

...
Чтобы отловить подробности ожиданий настрпойте сессию Extended Events с событиями Module start, Module end, Wait_info с соответствующими фильтрами.


Спасибо! Буду пробовать, у меня старый SSMS.
24 июн 19, 21:07    [21914405]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
invm
1klassNick
тут описано в каких единицах представлены поля в трассе
И что мешает привести их в запросе к одной единице?


В принципе можно, ...
24 июн 19, 21:12    [21914406]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
invm
Member

Откуда: Москва
Сообщений: 9349
1klassNick
Буду пробовать, у меня старый SSMS.
Скриптом надо, а не мышкой.
Примерно так:
create event session ... on server 
add event sqlos.wait_info(
    action(sqlserver.database_id, sqlserver.nt_username, sqlserver.plan_handle, sqlserver.session_id, sqlserver.sql_text)
    where (sqlserver.object_id = ... and sqlserver.database_id = ...)
),
add event sqlserver.module_end(
    action(sqlserver.database_id, sqlserver.nt_username, sqlserver.plan_handle, sqlserver.session_id, sqlserver.sql_text)
    where (sqlserver.object_id = ... and sqlserver.database_id = ...)
),
add event sqlserver.module_start(
    action(sqlserver.database_id, sqlserver.nt_username, sqlserver.plan_handle, sqlserver.session_id, sqlserver.sql_text)
    where (sqlserver.object_id = ... and sqlserver.database_id = ...)
)
...
24 июн 19, 21:27    [21914407]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
1klassNick
Member

Откуда:
Сообщений: 24
invm,

не получается установить фильтр по объекту в событии sqlos.wait_info...
26 июн 19, 13:42    [21915539]     Ответить | Цитировать Сообщить модератору
 Re: Как узнать какие ожидания или блокировки тормозят запрос  [new]
invm
Member

Откуда: Москва
Сообщений: 9349
1klassNick,

Действительно нельзя фильтровать wait_info по object_id.
Тогда, видимо, самое простое фильтровать по plan_handle процедуры.
26 июн 19, 14:14    [21915581]     Ответить | Цитировать Сообщить модератору
Все форумы / Microsoft SQL Server Ответить