grep всему голова

При разборе проблем, связанных с эксплуатацией 1С, анализ технологического журнала играет немаловажную роль. При этом объемы данных для анализа могут достигать приличных размеров. Что, в свою очередь, приводит к необходимости использования инструментов, обеспечивающих приемлемую скорость разбора файлов журнала. Например, использование утилит bash. В качестве вводной статьи могу порекомендовать ознакомиться с публикацией на ИТС. Практическое применение рассмотрим на примере анализа взаимоблокировок.

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

<log location="e:\tech_log\tlocks" history="24">
 <event>
  <eq property="Name" value="TLOCK"/>
 </event>
 <event>
  <eq property="Name" value="TTIMEOUT"/>
 </event>
 <event>
  <eq property="Name" value="TDEADLOCK"/>
 </event>
 <property name="all"/>
</log>

Можно разделить логи на блокировки и ожидания на блокировках, таймауты и дедлоки:

<log location="e:\tech_log\tlocks" history="24">
 <event>
  <eq property="Name" value="TLOCK"/>
 </event>
 <property name="all"/>
</log>
<log location="e:\tech_log\deadlocks" history="24">
 <event>
  <eq property="Name" value="TLOCK"/>
  <ne property="WaitConnections" value=""/>
 </event>
 <event>
  <eq property="Name" value="TTIMEOUT"/>
 </event>
 <event>
  <eq property="Name" value="TDEADLOCK"/>
 </event>
 <property name="all"/>
</log>

Допустим, действует первая настройка. Тогда я заходу в e:\tech_log\locks и вызываю консоль bash. Для начала мне нужно определить наличие проблем с блокировками.

grep -roP 'TDEADLOCK|TTIMEOUT|WaitConnections=\d+'

rphost_7188/17071415.log:WaitConnections=521711
rphost_7188/17071415.log:TDEADLOCK
rphost_7188/17071415.log:WaitConnections=521671
rphost_7188/17071415.log:WaitConnections=521711
rphost_8884/17071410.log:WaitConnections=519948

Или так:

grep -rlP 'TDEADLOCK|TTIMEOUT|WaitConnections=\d+'

rphost_7188/17071415.log
rphost_8884/17071410.log

Переходим к анализу событий TDEADLOCK, проанализируем файл журнала rphost_7188/17071415.log (62 Мб). После нескольких попыток получился следующий скрипт:

cat rphost_7188/17071415.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | sed -rn "s/(^.*?),TDEADLOCK,.*connectID=(.*?),SessionID.*,DeadlockConnectionIntersections='(.*),(.*)',Context='(.*)'.*/\1,\2\n>\3\n>\4\n\5/p"

31:37.377048-0,521711
>521711 521671 AccumRg48237.DIMS Exclusive Fld1765=0 Fld48238=271:80c3003048ff921111e600a432b00d3f Fld48239=658:80e2003048ff921111e76878525e8b59 Fld48240=T"20170701000000" Fld48241=253:80c4003048ff921111e604954845e95c Fld48241=253:80c4003048ff921111e60495663bf22e Fld48241=253:80c4003048ff921111e60495663bf231 Fld48242=555:00000000000000000000000000000000 Fld48243=253:80c4003048ff921111e6049e7e8fd1ef Fld48244=555:00000000000000000000000000000000 Period=[T"20170701000000":+] Splitter=1
>521671 521711 AccumRg47676.DIMS Exclusive Fld1765=0 Fld47677=253:80c4003048ff921111e6049596245b29 Fld47678=555:00000000000000000000000000000000 Fld47679=437:80c4003048ff921111e6054e24380748 Period=[T"20170701000000":+]
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаОбщийМодуль.мо_ПодпискиНаСобытия.Модуль : 49 : Выполнить(Обработчик + "(Источник, Отказ, РежимПроведения)");       : 1 : мо_ЗаказКлиентаСервер.ОбработкаПроведения(Источник, Отказ, РежимПроведения)           ОбщийМодуль.мо_ЗаказКлиентаСервер.Модуль : 1041 : ОбработкаИзмененияСтатуса(Источник);                   ОбщийМодуль.мо_ЗаказКлиентаСервер.Модуль : 1097 : РаспределениеПлана.Загрузить(РегистрыНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.ПолучитьТаблицуДвижений(Источник.Ссылка));                          РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.МодульМенеджера : 8 : Возврат ПолучитьТаблицуДвиженийДляЗаказаКлиента(Ссылка);                                        РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.МодульМенеджера : 33 : БлокировкаДанных.Заблокировать();

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

grep -P "^31:3.*t:connectID=(521711|521671).*AccumRg47676.DIMS Exclusive.*Fld47677=253:80c4003048ff921111e6049596245b29" *15.log

grep -P "^31:3.*t:connectID=(521711|521671).*AccumRg48237.DIMS Exclusive.*Fld48243=253:80c4003048ff921111e6049e7e8fd1ef" *15.log

Но такие команды будут обрезать контексты по первой строке, поэтому для получения всего текста я использовал следующий скрипт:

cat *15.log | awk -vORS= '{if(match($0, "^[0-9][0-9]\:[0-9][0-9]\.[0-9]+\-")) print "\n"$0; else print $0;}' | grep -P "^31:3.*t:connectID=(521711|521671).*(AccumRg47676.DIMS Exclusive.*Fld47677=253:80c4003048ff921111e6049596245b29 | AccumRg48237.DIMS Exclusive.*Fld48243=253:80c4003048ff921111e6049e7e8fd1ef)" | sed -r "s/(^.*?),TLOCK,.*connectID=(.*?),SessionID=(.*?),Usr.*Locks='(.*Exclusive|.*Shared).*',WaitConnections=(.*),Context='(.*).*'/\1,\2,\3,\4,\5\n\6/" > result.txt

31:34.142057-108993,521711,243,AccumRg48237.DIMS Exclusive,
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаДокумент.ЗаказКлиента.МодульОбъекта : 916 : ПроведениеСервер.ЗаписатьНаборыЗаписей(ЭтотОбъект); ОбщийМодуль.ПроведениеСервер.Модуль : 320 : Объект.Движения.Записать();
31:34.549009-15947,521711,243,AccumRg47676.DIMS Exclusive,
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаДокумент.ЗаказКлиента.МодульОбъекта : 916 : ПроведениеСервер.ЗаписатьНаборыЗаписей(ЭтотОбъект); ОбщийМодуль.ПроведениеСервер.Модуль : 320 : Объект.Движения.Записать();
31:35.064045-77979,521671,269,AccumRg48237.DIMS Exclusive,
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаДокумент.ЗаказКлиента.МодульОбъекта : 916 : ПроведениеСервер.ЗаписатьНаборыЗаписей(ЭтотОбъект); ОбщийМодуль.ПроведениеСервер.Модуль : 320 : Объект.Движения.Записать();
31:37.377052-15985,521711,243,AccumRg48237.DIMS Exclusive,521671
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаОбщийМодуль.мо_ПодпискиНаСобытия.Модуль : 49 : Выполнить(Обработчик + "(Источник, Отказ, РежимПроведения)");  : 1 : мо_ЗаказКлиентаСервер.ОбработкаПроведения(Источник, Отказ, РежимПроведения)  ОбщийМодуль.мо_ЗаказКлиентаСервер.Модуль : 1041 : ОбработкаИзмененияСтатуса(Источник);   ОбщийМодуль.мо_ЗаказКлиентаСервер.Модуль : 1097 : РаспределениеПлана.Загрузить(РегистрыНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.ПолучитьТаблицуДвижений(Источник.Ссылка));    РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.МодульМенеджера : 8 : Возврат ПолучитьТаблицуДвиженийДляЗаказаКлиента(Ссылка);     РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.МодульМенеджера : 33 : БлокировкаДанных.Заблокировать();
31:37.674030-2172022,521671,269,AccumRg47676.DIMS Exclusive,521711
Форма.Записать : Документ.ЗаказКлиента.Форма.ФормаДокументаДокумент.ЗаказКлиента.МодульОбъекта : 916 : ПроведениеСервер.ЗаписатьНаборыЗаписей(ЭтотОбъект); ОбщийМодуль.ПроведениеСервер.Модуль : 320 : Объект.Движения.Записать();

Как видно из результата, сеансы блокируют ресурсы в разном порядке. Рассмотрим сначала участок кода с контекстом "БлокировкаДанных.Заблокировать()". Сначала идет установка блокировки:

БлокировкаДанных = Новый БлокировкаДанных;
ЭлеменБлокировкиДанных = БлокировкаДанных.Добавить("РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов");
ЭлеменБлокировкиДанных.ИсточникДанных = ЗаказКлиента.мо_Комплектующие;
ЭлеменБлокировкиДанных.ИспользоватьИзИсточникаДанных("Комплектующая","Номенклатура");
ЭлеменБлокировкиДанных.ИспользоватьИзИсточникаДанных("КомплектующаяХарактеристика","Характеристика");
ЭлеменБлокировкиДанных.Режим = РежимБлокировкиДанных.Исключительный;

Следом идет запрос по остаткам регистра с параметрами виртуальной таблицы остатков:

ЗаказКлиента = ЗНАЧЕНИЕ(Документ.ЗаказКлиента.ПустаяСсылка)
 И Организация = &Организация
 И МесяцПланирования = &МесяцПланирования

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

ЭлеменБлокировкиДанных.УстановитьЗначение("ЗаказКлиента", Документы.ЗаказКлиента.ПустаяСсылка());
ЭлеменБлокировкиДанных.УстановитьЗначение("Организация", ЗаказКлиента.Организация);
ЭлеменБлокировкиДанных.УстановитьЗначение("МесяцПланирования", НачалоМесяца(ДатаОкончанияПериода));

Теперь проверим изменения. По журналу регистрации были найдены проблемные документы:

Дата, время	Сеанс	Событие	Данные	Комментарий
14.07.2017 15:31:13	243	Данные. Изменение	Заказ 0000-104142 от 11.07.2017 8:55:26
14.07.2017 15:31:13	243	Данные. Проведение	Заказ 0000-104142 от 11.07.2017 8:55:26
14.07.2017 15:31:22	269	Данные. Изменение	Заказ 0000-104253 от 14.07.2017 12:39:29
14.07.2017 15:31:22	269	Данные. Проведение	Заказ 0000-104253 от 14.07.2017 12:39:29
14.07.2017 15:31:37	243	ОшибкаОбработчика.Документ.ОбработкаПроведения	Заказ 0000-104143 от 11.07.2017 8:58:18	Ошибка выполнения обработчика мо_ЗаказКлиентаСервер.ОбработкаПроведения (ОбработкаПроведения). Ошибка: {РегистрНакопления.мо_РаспределениеПланаНаЗаказыКлиентов.МодульМенеджера(33)}: Ошибка при вызове метода контекста (Заблокировать): Конфликт блокировок при выполнении транзакции: Неустранимый конфликт блокировок
14.07.2017 15:31:45	269	Данные. Изменение	Заказ 0000-104253 от 14.07.2017 12:39:29
14.07.2017 15:31:45	269	Данные. Проведение	Заказ 0000-104253 от 14.07.2017 12:39:29
14.07.2017 15:31:53	243	Данные. Изменение	Заказ 0000-104143 от 11.07.2017 8:58:18
14.07.2017 15:31:53	243	Данные. Проведение	Заказ 0000-104143 от 11.07.2017 8:58:18

В отладочном сеансе на строку установки блокировки была сделана точка останова и один из документов был запущен на проведение. Во втором сеансе было выполнено проведение другого документ, который встал в ожидание. После этого в отладке было продолжено выполнение. И снова получаем взаимоблокировку. Дополнительная проблема оказалась в том, что движения по регистру AccumRg48237 формировались уже в подписке на событие ОбработкаПроведения, а в обработке проведения документа выполнялась команда Движения.Записать(). Что приводило к тому, что по проблемному регистру сначала записывался пустой набор записей. При этом, чтобы корректно удалить существующие движения в базе, устанавливаются управляемые блокировки по этим записям. Решение в этом случае следующее: отключить признак записи по регистру в процедуре обработки проведения модуля документа:

Движения.мо_РаспределениеПланаНаЗаказыКлиентов.Записывать = Ложь;

После выполнения повторного теста проблема взаимоблокировки ушла.