Добро пожаловать в форум, Guest  >>   Войти | Регистрация | Поиск | Правила | В избранное | Подписаться
Все форумы / Microsoft SQL Server Новый топик    Ответить
Топик располагается на нескольких страницах: [1] 2   вперед  Ctrl      все
 runnable forever  [new]
o-o
Guest
уважаемое сообщество, просьба поделиться идеями.

ситуация повторяется уже второй раз с перерывом в 2 недели.
из студии запускается процедура main, запускающая сотню других.
все удовольствие длится в среднем 2 часа, ни одна из инструкций не выполняется дольше 5 минут.
соответственно, если за 2 часа не завершается, запускатель идет выяснять, на чем висим.
и вот сегодня снова висит апдэйт, выполняющийся всегда за минуту.
висит час, висит 2.
в ожиданиях этой сессии НЕТ.
в sys.dm_exec_sessions сессия имеет статус running,
в sys.dm_exec_requests -- runnable.
все время runnable, не выходит из этого состояния.
как будто не пускают на процессор.
или пускают, но уж очень редко.
раз в 5 минут джоб мониторинга снимает фото сессий с их планом, блокировками, ридами.
на картинке показываю:
1) говернора нет
2) апдэйт, выдернутый из процедуры, выполняется за 56 секунд.
и план его такой же, вообще один в один с тем, что сохранился в мониторинге.
могу и картинками оба показать, и xml
3) никто не блокирует этот апдэйт, все локи грантед, риды растут, но крайне медленно.

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

ничего странного на сервере не запущено, все как всегда, тормозит тоже в пределах обычного.

у меня сохранены обе таблицы, участвующие в апдэйте, в соседней схеме на момент "непосредственно перед апдэйтом".
т.е. я просто делаю тому процессу kill,
беру скрипт процедуры, комментирую все, начиная с апдэйта и до конца,
запускаю.
сохраняю таблицы в соседнюю схему, навешиваю те же ПК, других индексов нет, в надежде на репро.
но как бы не так.
ни на этих сохраненных таблицах, ни на исходных в отдельно запущенном апдэйте, висючесть не повторяется.
запустив апдэйт, выдранный из процедуры (параметров НЕТ. ни в апдэйте, ни в процедуре,
ни вообще хоть в одной процедуре, это все просто перекачивание данных с денормализацией и агрегацией),
получаю актуальный план и статистику выполнения.
всего апдэйт делает 14.645.761 (логических) чтений одной таблицы и 11.402 второй.
а что я вижу в мониторинге:
за час висения этот апдэйт сделал 8.710.216 чтений.
в то время как за минуту своего выполнения вне процедуры он их сделал 14.657.163 и успешно завершился!

я раскомментариваю в процедуре апдэйт и все, что после него, запускаю снова эту процедуру и она завершается за 5 минут на все инструкции.

ну что после этого у процедуры новый план, то ок, но план апдэйта все тот же.
повторюсь, я сравниваю оценочный план, взятый из кэша на момент выполнения процедуры и сохраненный в мониторинге
и актуальный план этого же апдейта, выдранного из процедуры и запущенного отдельно.

тот же самый апдэйт в соседней схеме на ровно тех же данных выполняется за минуту все с тем же планом.
воспроизвести невозможно.
идей нет

К сообщению приложен файл. Размер - 144Kb
7 апр 16, 16:46    [19028903]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
+ update
set statistics io, time on;
update dbo.M_A_Variazioni_Portafoglio_Segmento_T
set 
	data_valido_al =			ps2.data_valido_al, 
	Min_IDBanca =				ps2.IDBanca, 
	Min_cod_portafoglio =		ps2.cod_portafoglio, 
	Min_TIPOPRATIC =			ps2.TIPOPRATIC
FROM dbo.M_A_Variazioni_Portafoglio_Segmento_T v
     INNER JOIN dbo.M_A_variazioni_PS2_T ps2
        ON v.NUM_PRAT = ps2.NUM_PRAT;

+ statistics

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.
Table 'M_A_Variazioni_Portafoglio_Segmento_T'. Scan count 1, logical reads 14645761, physical reads 12, read-ahead reads 23900, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'M_A_variazioni_PS2_T'. Scan count 1, logical reads 11402, physical reads 13, read-ahead reads 11398, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(2448883 row(s) affected)

(1 row(s) affected)

 SQL Server Execution Times:
   CPU time = 38625 ms,  elapsed time = 56335 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.

+ table scripts
CREATE TABLE [dbo].[M_A_Variazioni_Portafoglio_Segmento_T](
	[datarif] [date] NOT NULL,
	[NUM_PRAT] [int] NOT NULL,
	[IDBanca] [int] NOT NULL,
	[cod_portafoglio] [int] NOT NULL,
	[Tipo_contratto] [varchar](5) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
	[TIPOPRATIC] [int] NOT NULL,
	[DATACARICO] [date] NULL,
	[DATAOFFMAN] [date] NULL,
	[DATARICMAN] [date] NULL,
	[data_valido_al] [date] NULL,
	[Min_IDBanca] [int] NOT NULL,
	[Min_cod_portafoglio] [int] NOT NULL,
	[Min_Tipo_contratto] [varchar](5) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
	[Min_TIPOPRATIC] [int] NOT NULL,
	[Var_IDBanca] [int] NOT NULL,
	[Var_cod_portafoglio] [int] NOT NULL,
	[Var_TIPOPRATIC] [int] NOT NULL,
	[Cam_cod_portafoglio] [varchar](1) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
	[Cam_TIPOPRATIC] [varchar](1) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
	[Cambio portafoglio o segmento] [varchar](5) COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
	[Data Pass Soff] [date] NULL,
	[dtPassSoff] [int] NULL,
	[id_DATARICMAN] [int] NULL,
 CONSTRAINT [PK_M_A_Variazioni_Portafoglio_Segmento_T_100] PRIMARY KEY CLUSTERED 
(
	[NUM_PRAT] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON, FILLFACTOR = 100) ON [PRIMARY]
) ON [PRIMARY]


CREATE TABLE [dbo].[M_A_variazioni_PS2_T](
	[NUM_PRAT] [int] NOT NULL,
	[data_valido_al] [datetime] NOT NULL,
	[IDBanca] [int] NOT NULL,
	[cod_portafoglio] [int] NOT NULL,
	[TIPOPRATIC] [int] NOT NULL,
	[cnt] [int] NOT NULL,
 CONSTRAINT [PK_M_A_variazioni_PS2_T_100] PRIMARY KEY CLUSTERED 
(
	[NUM_PRAT] ASC,
	[TIPOPRATIC] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON, FILLFACTOR = 100) ON [PRIMARY]
) ON [PRIMARY]


К сообщению приложен файл (runnable_actual.sqlplan - 22Kb) cкачать
7 апр 16, 16:53    [19028945]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
WarAnt
Member

Откуда: Питер
Сообщений: 2423
o-o,

Когда у меня непонятные зависания в статусе running происходят, я начинаю смотреть на диск и на waittype,
если waittype = pagelatch_xx то далее смотрю банально скоростные данные диска, то есть read byte\sec и write byte\sec, уже несколько раз таким образом обнаруживалась проблема с хранилищем. когда нужно вычитывать много данных а скорость диска падает до 1-2 Мбайт в секунду, при том что в хороший солнечный день, этот же диск выдает 1-2 Гбайта в секунду, Очередь на диск при этом тоже показывает значения близкие к 0, далее звонок админам и через 10 минут все чудесным образом начинает летать, пытался у них потом выяснить причину, но от туда молчание или блеение в стиле, мы ничего не делали.
Если же waittype = sos_scheduler_yeild, то обычно, в сочетании с такой ситуацией, это значит кривой план. Тоесть можно опробовать хинтами его вправить.
7 апр 16, 17:02    [19028993]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
WarAnt
Member

Откуда: Питер
Сообщений: 2423
o-o,

у Вас на картинке к сожалению waittype не показан.
7 апр 16, 17:05    [19029013]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
WarAnt
o-o,
у Вас на картинке к сожалению waittype не показан.

19028903
o-o
в ожиданиях этой сессии НЕТ.

это означает, что сессии 125 НЕ БЫЛО в sys.dm_os_waiting_tasks на всем протяжении апдэйта.
он никогда вообще не suspended, он runnable. forever.
т.е. он освобождает процессор не потому что чего-то там ждет, а потому что исчерпал свой лимит.
сие называется SOS_SCHEDULER_YIELD, в ожидания не входит, в sys.dm_os_waiting_tasks не светится:
Randal, link below
The problem is that they’re not a real wait type, so you can’t use my script to look at sys.dm_os_waiting_tasks and get the query plans of threads incurring that wait type,
because these threads aren’t waiting for a resource, so don’t show up in the output of sys.dm_os_waiting_tasks!

Identifying queries with SOS_SCHEDULER_YIELD waits
7 апр 16, 17:16    [19029114]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
тот же джоб мониторит и пишет ожидания в таблицу dbo.wt:
единственное ожидание session_id = 125 за весь этот период на картинке.
это ровно в тот момент, когда ему делаю kill.
-- waiting_tasks simplified:
with cte as
(
select s.session_id, s.original_login_name, s.host_name, s.program_name, 
       wt.wait_type, wt.blocking_session_id, avg(wait_duration_ms) as avg_wait_duration_ms, 
       max(resource_description) as resource_description,         
       COUNT(*) as cnt
from sys.dm_os_waiting_tasks wt 
   join sys.dm_exec_sessions s
        on wt.session_id = s.session_id
where s.is_user_process = 1 
group by  s.session_id, s.original_login_name, s.host_name, s.program_name, 
       wt.wait_type, wt.blocking_session_id,
       case when wt.resource_description like 'exchangeEvent%' 
                then 'parallel'
            else wt.resource_description
       end
)


insert into  dbo.wt(dt, db, session_id, original_login_name, host_name, program_name, 
             wait_type, blocking_session_id, avg_wait_duration_ms, 
             resource_description, cnt, command, text, statement, query_plan)      

select getdate() as dt, DB_NAME(r.database_id) as db,
       c.*, r.command, t.text,
       case when t.encrypted = 1 then '-- encrypted'
            when r.statement_start_offset >= 0
             then substring(t.text, r.statement_start_offset/2 + 1,
                            case r.statement_end_offset
                                 when -1 then datalength(t.text)
                                 else r.statement_end_offset/2 - r.statement_start_offset/2 + 1
                            end)
       end as statement,       
       p.query_plan
from cte c 
     left join sys.dm_exec_requests r
       on c.session_id = r.session_id   
     outer apply sys.dm_exec_sql_text(r.sql_handle) t 
     outer apply sys.dm_exec_query_plan(r.plan_handle) p


К сообщению приложен файл. Размер - 73Kb
7 апр 16, 17:28    [19029173]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
WarAnt
Member

Откуда: Питер
Сообщений: 2423
o-o,

Смотрите на last_wait_type
7 апр 16, 17:33    [19029190]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
WarAnt
Member

Откуда: Питер
Сообщений: 2423
o-o,

Ваш запрос учитывает не все процессы, используйте лучше sysprocessese
7 апр 16, 17:41    [19029215]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
WarAnt
Member

Откуда: Питер
Сообщений: 2423
o-o

вот пример результатов запросов. Нет половины процессов:) в том числе SOS_SCHEDULER_YIELD

К сообщению приложен файл. Размер - 61Kb
7 апр 16, 17:51    [19029256]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
WarAnt
o-o,
Ваш запрос учитывает не все процессы, используйте лучше sysprocessese

ага, конечно, приведите плиз пример ожидания, к-ое не ловит sys.dm_os_waiting_tasks,
и я лично начну просить наших админов сдаунгрэйдится до 2000
WarAnt
o-o,
Смотрите на last_wait_type

процесс убит в районе 11 часов,
смотреть некуда.
народ требует хлеба и зрелищ данные для отчетов и не желает понимать,
что ситуевина уникальна и не воспроизводится по желанию.
нo специально для вас last_wait_type уже оглашен выше, SOS_SCHEDULER_YIELD.
в след. раз как повторится, я обязательно сделаю снимок sys.dm_exec_requests.
в смысле памятной картинки :)
7 апр 16, 17:55    [19029285]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
WarAnt
o-o

вот пример результатов запросов. Нет половины процессов:) в том числе SOS_SCHEDULER_YIELD

картинка неполная,
номера строк ни о чем не говорят, я схлопываю CX_PACKET в 1, потому что он мне закакивает таблицу:
with cte as
(
select s.session_id, s.original_login_name, s.host_name, s.program_name, 
       wt.wait_type, wt.blocking_session_id, avg(wait_duration_ms) as avg_wait_duration_ms, 
       max(resource_description) as resource_description,         
       COUNT(*) as cnt
from sys.dm_os_waiting_tasks wt 
   join sys.dm_exec_sessions s
        on wt.session_id = s.session_id
where s.is_user_process = 1 
group by  s.session_id, s.original_login_name, s.host_name, s.program_name, 
       wt.wait_type, wt.blocking_session_id,
       case when wt.resource_description like 'exchangeEvent%' 
                then 'parallel'
            else wt.resource_description
       end
)

сделайте SELECT DISTINCT wait_type и предъявите недостающее
7 апр 16, 18:01    [19029314]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
...и если верите мне на слово,
в sys.dm_os_waiting_tasks просто не было сессии 125,
не из таблицы мониторинга, а глазками в реальном времени.
именно этого не надо было бы даже схлопывать,
у него не было параллельности в плане
7 апр 16, 18:05    [19029338]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
Хочу переформулировать свой вопрос, а то из-за моего традиционного словесного поносадеревьев леса не видно.
Как понять, в чем проблема, когда в отсутствие говернора один-единственный процесс, не ждущий никакой ресурс, находится постояно в runnable-состоянии? Пока не убьешь сессию и (может быть) не перекомпилируешь, картинка повторяется, неизбежно доходя до одной и той же инструкции, где внезапно зависает, причем план как всегда и абсолютно ничего криминального не содержит, merge join, чего еще хотеть от жизни?
7 апр 16, 18:56    [19029554]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
MSSQLBug
Guest
o-o,

Наудачу (в ответе):
http://dba.stackexchange.com/questions/42827/troubleshooting-sos-scheduler-yield-wait
7 апр 16, 20:20    [19029791]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
MSSQLBug,

Спасибо, но там другая ситуация.
Там это ожидание выбилось в основные и страдают там от этого все.
А тут в целом по серверу температура нормальная,
и в этой же сессии все остальное выполнялось за обычное время (это каждый день выполняется, статистика накоплена).
В топе ожиданий у нас все как всегда, CX_PACKET и PAGEIOLATH, хотя у нас и перегрузили сервер день назад, т. е. статистика всего за сутки и если б это было у всех, вылезло бы на первые места.
Непонятно, на что думать. Из всех процедур выбирается всего одна, далеко не первая, а в ней тоже вовсе не первая инструкция.
Главное, эту процедуру вчера меняли, правда не в части апдэйта, и отработала она без зависания. А сегодня повторилась ситуация от 21ого марта, когда эта процедура была немного по-другому написана.
Мне сообщают не когда вместо минуты 10 провисело, а когда час-два висит, а им срочно надо данные. И я не успеваю придумать, что еще отмониторить, надо срочно расправляться с этой ситуацией...
Если сейчас кто-то что-то подскажет, посмотрю, как только снова повторится
7 апр 16, 20:54    [19029919]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
Glory
Member

Откуда:
Сообщений: 104751
reads/writes/cpu_time меняются хоть ?
7 апр 16, 21:14    [19029979]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
Да, менялись. Но в час по чайной ложке.
Т. е. у меня в первом посте на картинке приведены значения, и далее по тексту сколько чтений он за час сделал: меньше, чем тот же сервер в том же запросе, отработавшем за минуту.
Впечатление такое, что не давали ему работать.
Не пускали на процессор
7 апр 16, 21:19    [19029996]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
MSSQLBug
Guest
o-o
Непонятно, на что думать.

Например, на MS SQL Bug. ;)

o-o
она раз 5 перезапустила одиночную процедуру и убила на этом еще час.

Особенно "радует" вот это. :(

o-o
всего апдэйт делает 14.645.761 (логических) чтений одной таблицы и 11.402 второй.
а что я вижу в мониторинге:
за час висения этот апдэйт сделал 8.710.216 чтений.
в то время как за минуту своего выполнения вне процедуры он их сделал 14.657.163 и успешно завершился!

В порядке бреда: ну а если всё же не поверить в одинаковые планы и (в следующий раз) проверить (запросом с NOLOCK, например) сколько записей было обновлено при 8.710.216 чтениях? Количество должно было быть примерно: [кол-во записей в таблице] * 8.710.216 / 14.657.163, правильно?
7 апр 16, 22:15    [19030167]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
Crimean
Member

Откуда:
Сообщений: 13147
а вы таки уверены, что в это время план не скатывается в LOOP?
нельзя пускать трас по этому процессу, а?
со снятием планов?
8 апр 16, 01:57    [19030579]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
Думаю, с лупами за час-два чтений бы столько было, что глядя на них можно было бы заподозрить.
Попробую сегодня ему насильно лупы прописать и оглашу чтения за 10 минут.
8 апр 16, 08:19    [19030819]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
Glory
Member

Откуда:
Сообщений: 104751
может у вас настроен resource governor ?
8 апр 16, 09:28    [19030988]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
с лупами ничуть не хуже:
Warning: The join order has been enforced because a local join hint is used.
Table 'M_A_Variazioni_Portafoglio_Segmento_T'. Scan count 1, logical reads 7386079, physical reads 12, read-ahead reads 39426, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'M_A_variazioni_PS2_T'. Scan count 2504660, logical reads 8014765, physical reads 11339, read-ahead reads 14, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(2448883 row(s) affected)

(1 row(s) affected)

 SQL Server Execution Times:
   CPU time = 34859 ms,  elapsed time = 49347 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.
8 апр 16, 09:29    [19030991]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
а вот и hash:
 SQL Server Execution Times:
   CPU time = 0 ms,  elapsed time = 0 ms.
Warning: The join order has been enforced because a local join hint is used.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 7 ms.
Table 'M_A_Variazioni_Portafoglio_Segmento_T'. Scan count 5, logical reads 7386333, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'M_A_variazioni_PS2_T'. Scan count 5, logical reads 11473, physical reads 0, read-ahead reads 48, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(2448883 row(s) affected)

(1 row(s) affected)

 SQL Server Execution Times:
   CPU time = 16813 ms,  elapsed time = 10732 ms.
8 апр 16, 09:31    [19030999]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
куда еще мог скатиться план???
8 апр 16, 09:32    [19031004]     Ответить | Цитировать Сообщить модератору
 Re: runnable forever  [new]
o-o
Guest
ну и снова merge, для коллекции
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.
Warning: The join order has been enforced because a local join hint is used.
SQL Server parse and compile time: 
   CPU time = 6 ms, elapsed time = 6 ms.
Table 'M_A_Variazioni_Portafoglio_Segmento_T'. Scan count 1, logical reads 7386079, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'M_A_variazioni_PS2_T'. Scan count 1, logical reads 11402, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(2448883 row(s) affected)

(1 row(s) affected)

 SQL Server Execution Times:
   CPU time = 21922 ms,  elapsed time = 24298 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.
8 апр 16, 09:35    [19031008]     Ответить | Цитировать Сообщить модератору
Топик располагается на нескольких страницах: [1] 2   вперед  Ctrl      все
Все форумы / Microsoft SQL Server Ответить