Двенадцать одновременных вызовов к опубликованной базе. Десять отработали за восемь секунд, два - за шестнадцать. Ошибки не было ни одной, все двенадцать вернули 200. Просто два запроса из двенадцати стояли в очереди ровно столько, сколько шёл самый долгий сосед.
Это стенд, и цифры ниже все оттуда. А боль, из-за которой мы туда полезли, обычная: через публикацию ходят тяжёлые сервисные вызовы, и время от времени сервисы перестают отвечать. Ни ошибки, ни записи в журнале регистрации, сервер 1С по метрикам здоров, СУБД не нагружена.
Разбор о том, где на самом деле стоит эта очередь, почему её не видно в привычных местах и что мы померили, чтобы перестать гадать.
Почему первая догадка обычно неверна
Когда сервис перестаёт отвечать, смотрят в трёх местах: рабочие процессы кластера, ожидания СУБД, журнал регистрации. Логика понятная: раз не отвечает, значит что-то внутри застряло.
И все три места показывают, что всё хорошо. Инструменты при этом не врут, они смотрят не туда.
Очередь стоит до сервера 1С. Запрос приходит на веб-сервер, веб-сервер должен взять свободное соединение с сервером 1С из своего пула, и если свободных нет, запрос ждёт. В журнале регистрации его не будет по простой причине: сеанс ещё не создан, писать туда нечего. В метриках кластера его тоже нет, потому что до кластера он не дошёл.
Здесь стоит развести два похожих состояния, потому что лечатся они по-разному. Завис процесс - это снятие дампа и обращение в поддержку, про этот случай я писал отдельно. Завис вызов при живом процессе - это очередь, и дамп здорового рабочего процесса покажет ровно ничего. Снаружи оба выглядят одинаково: сервис не отвечает.
Значит при чистых метриках кластера и СУБД следующим местом надо смотреть мельче, на входе в публикацию.
Где живёт этот пул
В файле публикации default.vrd, который лежит в каталоге публикации на веб-сервере. Элемент называется pool и стоит на уровне всей публикации:
<pool size="10000" maxAge="300" attempts="5" attemptTimeout="1000"
waitTimeout="500" serverPingTimeout="15000" serverPingPeriod="3000" />
Здесь придётся быть точным, иначе получится популярное, но неверное утверждение. Конфигуратор параметры пула пишет. При публикации он проставляет reuseSessions, sessionMaxAge, poolSize и poolTimeout у каждой точки: у каждого веб-сервиса, у каждого HTTP-сервиса, у OData (протокол доступа к данным по HTTP, который платформа публикует вместе с базой).
Чего он действительно не пишет, так это отдельного элемента pool уровня публикации. Это другой уровень, живущий своей жизнью. Строку с ним дописывают руками, и обычно только те, кто уже поймал зависание.
Элемент появился в платформе 8.3.9.1818 - это из документации, не из наших замеров. То есть он есть у всех, кто читает этот текст, и вопрос только в том, стоит ли он у вас.
Откройте свой default.vrd и поищите в нём строку <pool. Нет её - публикация работает на умолчаниях, и дальше именно про них.
Замер первый: сколько тянет публикация без этой строки
Стенд простой и воспроизводимый: IIS (Internet Information Services, веб-сервер Windows) версии 10.0, сервер 1С на той же машине, типовая конфигурация, платформа 8.3.27.1606. В базе HTTP-сервис, который умеет выполнить переданный код. Нагрузка - двенадцать параллельных вызовов, каждый занимает сервер ровно восемь секунд.
Элемента pool в файле нет, у точек стоит проставленное конфигуратором.
| Вызовы | Старт | Длительность |
|---|---|---|
| десять из двенадцати | 0,00-0,19 с | ~8,2 с |
| оставшиеся два | 0,15-0,19 с | ~16,2 с |
Весь прогон занял 16,3 секунды. Десять вызовов прошли одной волной, одиннадцатый и двенадцатый дождались второй и заняли вдвое больше времени. Отказа не получил никто.
Это и есть механизм жалобы. Пользователь не видит ошибки, он видит, что "иногда подтормаживает", а под ровной нагрузкой - что "сервис висит". Никакого отказа в логах при этом нет, потому что отказа и не было.
Оговорка про формулировку порога. Замер шёл по одному HTTP-сервису, и разделить "десять на публикацию" и "десять на точку" им нельзя. Пишу так, как показал прогон: десять одновременных вызовов на сервис. Если у вас пять живых сервисов и порог окажется на точку, арифметика будет другая, и это надо проверять у себя.
Замер второй: доказать, что дело именно в size
Первый замер можно было объяснить совпадением: десятка в волне и poolSize="10" у точек публикации подозрительно похожи. Пока это не разведено, писать "предел задаётся размером пула" нельзя.
Разводится одним прогоном. В файл дописывается <pool size="3"/>, пул приложений перезапускается, всё остальное не трогается. У точек poolSize как стоял 10, так и остался.
| Волна | Сколько вызовов | Длительность |
|---|---|---|
| первая | 3 | ~8,7 с |
| вторая | 3 | ~16,7 с |
| третья | 3 | ~24,8 с |
| четвёртая | 3 | ~32,7 с |
Ровно по три в волне, четыре волны, двенадцать вызовов. Весь прогон занял 32,8 секунды против 16,3 на умолчаниях. Все двенадцать вернули 200.
Значит ширину волны задаёт атрибут size элемента уровня публикации. Настройка точки при этом никуда не делась и продолжает управлять своим - пулом сеансов, а он про другое.
Честная оговорка: замер не различает, откуда берётся сама десятка при отсутствии элемента. Платформенное умолчание это или наследование от точки - неизвестно. Для практики разницы нет, порог одинаков, но утверждать "умолчание равно десяти" я не буду. Ведёт себя как десять - да.
Отсюда следует практическое: size ставится под реальную одновременность. Держать его "побольше на всякий случай" смысла нет: считается она по числу параллельных интеграций плюс запас.
Замер третий: в чём измеряются таймауты
Дальше самое неприятное, потому что документация расходится сама с собой. В одном месте атрибуты attemptTimeout, waitTimeout, serverPingTimeout описаны как миллисекунды, а в примерах, которые ходят по статьям, встречается attemptTimeout="0.5", что читается как секунды.
Разница в тысячу раз, и она определяет, что стоит в вашем боевом файле. Померили отдельным тестом: в файл кладётся <pool size="1"/>, то есть публикации оставлено одно соединение, длинный вызов на тридцать секунд его занимает, и через три секунды приходит второй, лёгкий.
| attemptTimeout | waitTimeout | Что стало со вторым запросом |
|---|---|---|
| 1000 | 3000 | ждал 27,84 с и получил успешный ответ |
| 2 | 2 | оборвался через 2,05 с с 502 Bad Gateway |
Значение "2" дало ровно две секунды. Будь единицей миллисекунда, отказ пришёл бы через две тысячных, а значения 1000 и 3000 оборвали бы ожидание на первых секундах, чего не произошло. Единица измерения - секунды.
Оговорка. Чего этот тест не различает: в обоих прогонах менялись attemptTimeout и waitTimeout одновременно. Единица у них общая, а кто именно рвёт ожидание - неизвестно. И serverPingTimeout с serverPingPeriod не проверялись вовсе, перевод их в человеческие единицы ниже сделан по аналогии, замера по ним не было.
Теперь посмотрите на строку из начала статьи глазами этого замера. attemptTimeout="1000" это не одна секунда, а шестнадцать минут. waitTimeout="500" - восемь минут. Если аналогия верна и для пинга, serverPingTimeout="15000" - больше четырёх часов.
То есть в боевой настройке, которая вылечила зависание, таймауты выставлены в "ждать практически вечно". Лечили не они. Лечил size="10000": пул перестал быть узким местом, очередь исчезла.
Если у вас в файле стоят четырёхзначные таймауты, переведите их в человеческие единицы и посмотрите, что получится. Скорее всего, отказа по таймауту у вас не будет никогда. Зависший вызов при этом держит слот до перезапуска.
Отклонённая гипотеза: помогла строка или помог перезапуск
Правку в боевой файл вносят вместе с перезапуском, поэтому объяснение "помог не пул, а перезапуск" остаётся живым: перезапуск сам по себе сбрасывает зависшие сеансы. Гипотезу надо было либо подтвердить, либо убить.
Она оказалась не альтернативой, а второй половиной ответа. Тот же тест с size="1", но прочитанный с другой стороны - что было до перезапуска и что после:
| Состояние | Длинный вызов | Короткий вызов |
|---|---|---|
| до перезапуска | 29,73 с | 0,10 с |
| после перезапуска | 30,83 с | 27,84 с |
Это один прогон, прочитанный дважды: строка "после перезапуска" и есть первая строка предыдущей таблицы. До перезапуска ограничение не действовало вовсе - короткий вызов прошёл мгновенно, значит соединение ему нашлось. После перезапуска он честно отстоял очередь.
Вывод отсюда важнее самого замера. Работающий процесс держит настройки публикации в своей копии в памяти и файл не перечитывает. Перезапуск - это способ доставить правку до работающей публикации, и другого способа нет.
В нашем прогоне перезапускался весь веб-сервер. Хватит ли рециклинга одного пула приложений, мы отдельно не проверяли, хотя по механизму должно хватать: перечитывание происходит при старте рабочего процесса.
Практическое отсюда простое: дописать строку и не перезапустить - то же самое, что не дописывать её вовсе.
Отсюда проверка, которую нельзя сделать с одной стороны
Если правка вступает в силу только с перезапуском, значит существует целый класс публикаций, где строку дописали, а пул не перезапускали. Настройка лежит на диске, публикация работает по старому, и человек уверен, что всё настроено.
Проверяется одним сравнением: дата изменения default.vrd против времени старта рабочего процесса (w3wp - процесс, в котором IIS выполняет приложение). Файл новее процесса - правка не применена.
Неприятность в том, что ни одна сторона не отвечает сама. Изнутри 1С видна дата файла, но не время процесса веб-сервера. Со стороны веб-сервера видно время процесса, но никто не знает, что этот файл вообще правили. Нужны обе половины сразу.
Проверить у себя можно прямо сейчас. Дата файла - свойства, вкладка "Общие". Время старта процесса диспетчер задач не показывает, там такой колонки нет ни на одной вкладке, поэтому берём PowerShell:
Get-Process w3wp | Select-Object Id, StartTime
Оговорка. Учтите заранее: чтение конфигурации IIS требует прав администратора. Без них модуль администрирования ошибки не выдаёт: он тихо возвращает пустые значения, и это отдельная ловушка - пустота выглядит как "всё в порядке".
Замер четвёртый: время жизни сеанса вдвое больше написанного
Это уже другой пул - пул сеансов, тот самый, который конфигуратор пишет сам. У каждой точки стоит sessionMaxAge, и по нему считают, сколько сеансов и лицензий съест публикация под нагрузкой.
Проверили. Нагрузка из пяти параллельных вызовов создаёт пять-семь сеансов, дальше вызовы прекращаются, и раз в несколько секунд снимается список сеансов базы.
| Прогон | Шаг наблюдения | Номинал | Фактическая смерть |
|---|---|---|---|
| первый | 10 с | 20 с | между 40-й и 50-й секундой |
| второй | 5 с | 20 с | между 40-й и 45-й секундой |
Номинал двадцать, реальность сорок с лишним. Два независимых прогона с разным шагом наблюдения дали один результат.
Похоже, протухание проверяется не непрерывно, а с периодом, равным самому значению - отсюда разброс от одного номинала до двух. Механизм я утверждать не берусь, померено одно значение номинала, а число воспроизводится.
И второе, что вылезло в том же прогоне: параметр меряет простой, а не возраст. Сеанс, который дёргают раз в пять секунд, не умер за 107 секунд наблюдения. Это и есть потолок утверждения: дольше мы не смотрели.
Считать потребность в сеансах и лицензиях стоит по удвоенному номиналу - с той же оговоркой, что замер был один.
Заодно про 502 и 401.5, раз уж мы в кодах
Из замера с таймаутами вылезла деталь, которая стоит отдельного абзаца. Когда пул исчерпан и ожидание оборвалось, приходит 502 Bad Gateway.
502 рядом с 1С привычно читают как "сервер 1С отвалился" и идут смотреть кластер. А он может означать, что запрос не дождался свободного соединения на веб-сервере. Сервер при этом жив и здоров.
Различать эти два случая надо по тому, кто отдал код. 502 от вашего собственного переходника или прокси обычно и правда означает "до базы не достучались", и повтор запроса там осмыслен. 502 от веб-сервера по истёкшему ожиданию означает очередь, и повтор просто встанет в неё следом. Автоматика, которая перезапрашивает на 502 не глядя, во втором случае удлиняет очередь.
Второй код из той же серии - 401.5. Его читают как "IIS не пускает" и начинают чинить аутентификацию. Подкод 5 означает отказ самого расширения ISAPI (Internet Server API, интерфейс, через который IIS вызывает модуль 1С), то есть отказ пришёл со стороны 1С. Про этот случай я писал отдельно: там причиной оказалась кодировка логина на стороне клиента. Здесь важно одно: подкод 5 отправляет чинить не ту сторону.
Для иллюстрации - логи IIS нашего стенда за неделю: 97 записей 500.0, тринадцать 401.5 и две 502.0. И вот что тут показательно: почти все эти записи оставили мы сами. Тринадцать 401.5 - наши прогоны с кириллическим логином, две 502.0 - ровно те отказы из замера таймаутов, что в таблице выше. Подкод сразу говорит, кто наследил, а сводка "у нас 97 пятисоток" не говорит ничего.
Границы применимости
Чтобы никто не унёс отсюда больше, чем здесь есть.
- Всё померено на IIS. Про Apache я ожидаю того же механизма, потому что пул соединений реализован на стороне платформы, и веб-сервер тут только транспорт, но чисел оттуда у меня нет и проверять это надо отдельно.
- Одна версия платформы, 8.3.27.1606. На 8.3.9, где элемент появился, поведение может отличаться.
- Стенд однопользовательский и синтетический. Каждый вызов занимает сервер ровно восемь секунд. На боевой нагрузке картина размазаннее.
- Один сервис в замере. Отсюда неразведённое "на публикацию или на точку".
- Откуда берётся десятка при отсутствии элемента - не разведено.
attemptTimeoutиwaitTimeoutне разделены между собой.attempts,serverPingTimeoutиserverPingPeriodне проверялись вовсе.
Инструмент
Проверки из этого разбора собраны в отдельную обработку: Чек-ап веб-публикации. Она снимает свою половину сама, а по стороне веб-сервера печатает скрипт администратору и разбирает его ответ обратно, сводя обе половины в один вердикт. В настройки IIS ничего не пишет.
Вопрос к тем, кто дочитал
Посмотрите дату своего default.vrd и время старта рабочего процесса. У скольких из вас файл новее процесса, то есть публикация прямо сейчас работает по не тому, что в нём написано?
И второй, для тех, у кого элемент pool стоит: какие значения там прописаны и откуда они взялись - посчитаны или скопированы из чужой статьи? Мне интересно, насколько распространён случай "скопировали чужие таймауты и получили ожидание длиной в четыре часа".
Вступайте в нашу телеграмм-группу Инфостарт