Расследование блокировок и снижения производительности на одном примере

Причины начала расследования

На одном их проектов от пользователей начали поступать жалобы на низкую производительность при работе с системой. На SQL сервере с помощью Activity Monitor была обнаружена блокировка, из-за которой увеличивалась очередь запросов к базе данных.  (прочитать об Activity Monitor можно на MSDN)

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

Расследование

Наша задача заключалась в том, чтобы найти причину блокировок и избавиться от них.

Первоначально было известно, что блокировки возникают в дневное время. Для обнаружения причины блокировок мы обратились к Activity Monitor. В нем можно отследить цепочку блокировок и обнаружить главный блокирующий процесс для дальнейшего анализа в профайлере. Для этого нам необходимо посмотреть на поле «Блокирующий сеанс». В этом поле мы видим идентификатор блокирующего сеанса, так же есть поле главная причина блокировки, в котором числом 1 отмечается сеанс, являющийся главной причиной блокировки в цепочке блокировок. Вызвав контекстное меню кликнув правой кнопкой мыши на блокирующем сеансе, выбираем пункт «Подробности». В появившемся окне предоставлена информация о последнем выполненном запросе или выполняющийся запрос (все зависит от состояние процесса, например, если сеанс в состоянии Running мы увидим текущий выполняющийся запрос, если в состоянии Sleeping, то увидим последний выполненный запрос).

Благодаря  Activity Monitor  мы смогли обнаружить блокирующий сеанс и  последний запрос в рамках блокирующей транзакции. Он выглядит следующим образом:

/*isbl*/
    select 
      a.Analit
    from
      MBAnalit a
    where 
      a.Vid = 3408
      and a.Analit <>  657490
      and a.MestoReg = 158892
      and a.GruppaDel = 458598
      and a.DataTime >= ‘01.01.2015’
      and a.DataTime <= ‘31.12.2015’
      and a.Dop = ‘353’

По префиксу  /*isbl*/ в тексте запроса можно понять, что он выполняется в прикладном коде. Похожий sql запрос был найден в 2-х местах, в событии «сохранение до» справочников ОИВ РКК и ОИВ Обращения граждан и организаций, но по ограничению в запросе ‘a.Vid = 3408’ можно понять, что это справочник ОИВ РКК.

Трэйсы показали, что запрос выполняется моментально, кроме того запросы из прикладной имеют уровень изоляции транзакций read uncommitted. Этот подразумевает, что транзакции, выполняющие только чтение, при данном уровне изоляции никогда не блокируются (почитать про уровни изоляции можно на wikipedia и msdn). Отсюда следует, что причиной блокировок не мог быть этот запрос.

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

Профайлер был настроен на запись данных в таблицу и были включены следующие события:

• Blocked process report;
• Lock:DeadLock;
• ExistingConnection;
• RPC:Complete;
• SP:Complete;
• SP:recompile;
• SP:Starting;
• SP:StmtCompleted;
• SP:StmtStarting;
• SQL:BatchCompleted;
• SQL:BatchStarting;
• SQL:StmtCompleted.

Так же был запущен еще 1 профайлер с теми же событиями, но ограниченный по Duration  >= 5 мин. В него попадала только информация по Blocked process report, т.к. остальные действия выполнялись быстро.Так же мониторили состояние сервера с помощью Activity Monitor.

Обнаружив в Activity Monitor ИД блокирующего и блокируемых сеансов мы приступили к анализу профайлера. Нам необходимо определить транзакцию, которая накладывает блокировку, для этого ищем её в профайлере по ИД блокирующего сеанса, полученного из Activity Monitor.

Далее определяем последовательность действий в рамках блокирующей транзакции. Процесс долгий и описывать его тут не будем.

Следующим шагом будет определение какой процесс и запрос были заблокированы. Для этого находим в Activity Monitor запрос в состоянии suspended с ИД главного блокирующего сеанса.  Заблокированный запрос выглядел следующим образом:

create table #SBIndexDataTaskTempIDs (TaskID int)
insert into #SBIndexDataTaskTempIDs (TaskID)
select
  XRecID
from
  SBTask
where not exists (
  select
    TaskID
  from
    SBIndexDataTask
  where
    SBTask.XRecID = SBIndexDataTask.TaskID)
create index ID on #SBIndexDataTaskTempIDs (TaskID)

Если посмотреть где используется этот запрос, то выясняем, что это индексирование полнотекстового поиска, который запускается планировщиком windows каждый час. Судя по запросу мы можем предположить, что блокируется на самом деле таблица SBTask.

Для подтверждения блокировки таблицы  SBTask следующим шагом был анализ события Blocked Process Report.

В событии Blocked Process Report отображается подробная информация по блокировкам в виде xml.

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

	
		
			
				
			
			
create table #SBIndexDataTaskTempIDs (TaskID int)
insert into #SBIndexDataTaskTempIDs (TaskID)
select
  XRecID
from
  SBTask
where not exists (
  select
    TaskID
  from
    SBIndexDataTask
  where
    SBTask.XRecID = SBIndexDataTask.TaskID)
create index ID on #SBIndexDataTaskTempIDs (TaskID)   
		
	
	
		
			
			
/*isbl*/ 
    select 
      a.Analit
    from
      MBAnalit a
    where 
      a.Vid = 3408
      and a.Analit <> 657490
      and a.MestoReg = 158892
      and a.GruppaDel = 458598
      and a.DataTime >= '01.01.2015'
      and a.DataTime <= '31.12.2015'
      and a.Dop = '353'   
		
	

В этой XML мы снова видим блокируемый процесс и блокирующий процесс, но с собранной воедино полезной информацией. Блокируемый процесс в отчете отображается как , здесь мы видим сам запрос и параметры процесса. Из отчета получаем следующую информацию: заблокированный процесс запущен под учетной записью loginname="DOMEN\UserName" на машине  hostname="DIR-WF", с самым строгим уровнем изоляции isolationlevel="serializable", процесс находится в статусе status="suspended" ожидания освобождения ресурса waitresource="KEY: 5:72057601332412416 (9e4f283eedb7)", и блоркировка наложена не на весь ресурс а на некоторую область  lockMode="RangeS-S". Благодаря waitresource="KEY: 5:72057601332412416 (9e4f283eedb7)" можно точно определить какой ресурс не может получить блокированный процесс, для этого надо выполнить простенький запрос:

select
  *
from
  sys.objects where object_id = (select object_id from sys.partitions
where hobt_id = 72057601332412416)

где 72057601332412416 – часть параметраKEY: 5:72057601332412416 (9e4f283eedb7) .

В результатах запроса видно, что ID  72057601332412416 у таблицы SBTask.

Результат расследования и принятые меры

На основе полученных данных вырисовывается следующая картина: в рамках отработки ТМ на WF создается задача и блокируется некоторая область в sbtask для отработки вставки задачи в рамках транзакции, создаются поручения, но транзакция не успевает завершиться и в этот момент запускается индексирование текстов и слепков объектов, индексирование в свою очередь блокирует всю таблицу SBtask, т.к. уровень изоляции serializable. Но он не может завершиться из-за блокировки области в таблице, наложенной от прошлой транзакции. Транзакция вставляющая запись в таблицу переходит в состояние sleeping, и не завершается, в итоге накапливаются в очереди процессы на обработку, что приводит к замедлению работы всего и вся, включая проводник.

Индексирование запускалось каждый час планировщиком заданий Windows. Такое частое выполнение индексирования в рабочее время не очень хороший вариант для больших баз, т.к. нагружает базу и замедляет её работу, к тому же как видно могут возникать блокировки. Было решено перенести индексирование на вечернее время, когда нагрузка на базу минимальна. После переноса индексирования на вечернее время, блокировок больше не возникало.