Левиафан закрытия месяца, или Три охотника за временем

Меня зовут Стелла. Несколько лет назад — неважно, сколько именно — я работала главным бухгалтером розничной сети, и почти каждый конец месяца я отправлялась на охоту. Не за китом, нет. За временем, которое у меня крали.

Каждый 10-й рабочий день нового месяца я приходила в офис затемно, наливала кофе и запускала помощник закрытия. Потом садилась и ждала. Более 3 часов — таков был обычный срок. За это время сервер, стоявший в прохладной комнате этажом ниже, перебирал 40 000 документов, как старый библиотекарь, который перечитывает каждую карточку каталога, хотя половину мог бы пропустить. Я не знала этого тогда. Я просто ждала и смотрела, как ползёт прогресс‑бар, медленнее, чем тень от облачного столба пересекает залив в штиль.

База наша была тяжела — 70 ГБ, 1 организация, но поток поступлений по эквайрингу шёл, как Гольфстрим: неутомимо, непрерывно, ежедневно. PostgreSQL под Linux, платформа 8.3.27, оценка МПЗ по ФИФО. Сервер 1С имел 14 ядер, но во время перепроведения работал, по сути, 1 ядром. Как галера с сотней гребцов, где весло держит только один, а остальные смотрят на волны.

Я не раз говорила нашим технарям: 3 часа — это невыносимо. Закрытие месяца должно быть рутиной, а не одиссеей. Мне отвечали: «База большая, документов много, так работает 1С». Мне хотелось спросить: а почему тогда остальные документы проводятся за доли секунды, а банковские выписки тянутся, как смола в декабре? Но я не умела читать технологические журналы и не знала слов «pg_stat_statements» или «auto_explain». Я просто знала, что где‑то в недрах базы прячется зверь, пожирающий моё время.

И однажды я решила, что больше не хочу ждать. Я позвала на борт 2 человек.

Глава II. Инженер

Первым пришёл Вениамин, системный инженер. Человек тихого нрава и пристального взгляда, он говорил мало, но каждое слово его было, как звёздочка на карте: точное и не лишнее. Он не верил в чудеса и не искал быстрых решений. «Прежде чем резать, — сказал он, — нужно увидеть, где болит».

Вениамин начал с PostgreSQL. Это было его море, и он знал его течение.

Что увидел инженер на дне

Он проверил чтение с диска: попадания в кэш — 99,93%. За 82 минуты — 11,5 секунд чтения и 4,9 секунды записи. Диск не был виноват. Он проверил временные файлы: за апрель — ни одного; в ночных прогонах мая — горстка, 3–6 файлов общим объёмом 0,4–0,9 ГБ. Сортировки не сбрасывались на диск. Он проверил локальные буферы: доля попаданий — 99,36%, в среднем 3,8 блока на вызов. Буферов хватало. Он проверил блокировки: ни одного TLOCK длиннее 1 секунды, ни одного тупика, ни одного ожидания. Море было спокойно.

Он проверил состояние таблиц: мёртвых строк — 0,2–0,6%. Статистика актуальна. Обслуживание не объясняло задержку. Он проверил параллельное выполнение: отдельный SELECT уходил в PostgreSQL с 3 параллельными рабочими процессами, но тот же запрос в составе INSERT INTO pg_temp … SELECT — без них. Именно в такую конструкцию 1С преобразовывала запрос с ПОМЕСТИТЬ. Увеличение числа параллельных процессов не помогало. Он проверил групповую фиксацию: за 4 866 отсчётов медиана одновременно пишущих транзакций — 1, максимум — 2–4. Писателей было мало.

Всё, что он нашёл, говорил: сервер не перегружен. В ночную серию СУБД в среднем использовала 0,55–0,86 ядра из 4. Пиковая загрузка рабочего процесса 1С достигала 2,6 ядра. Темп — 50–66 фиксаций в секунду. Добавлять память, диски или ядра не имело смысла.

Зверь был не в море. Зверь был в трюме.

Трюмные доски

Тогда Вениамин спустился в код. Он снял время по видам документов, используя журнал регистрации, и увидел распределение:

Больше 50% всего времени — на поступлениях на расчётный счёт. 20 000 документов, каждый по 300 миллисекунд. Это была не случайность. Это была закономерность, и закономерность эта имела форму.

По pg_stat_statements он выделил дорогой шаблон запроса. Через auto_explain получил план. По свойству Context технологического журнала нашёл вызывающий код:

Один запрос. одна строка результата. Но чтобы её получить, план обрабатывал 1 строку итогов и 19 797 строк движений. 102 436 обращений к буферам на выполнение. Данные лежали в кэше — основная работа — это работа процессора.

Левиафан

Вот что обнаружил Вениамин, и вот что я хочу объяснить вам так, как он объяснил мне.

Запрос обращался к виртуальной таблице остатков регистра бухгалтерии Хозрасчетный с отбором по организации, контрагентам и договорам:

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

Для 1 договора эквайринга Вениамин подсчитал последующие движения после момента выписки:

На этот договор приходились 19 555 из 21 474 июльских поступлений — около 91%. Каждое поступление снова запрашивало остаток по тому же договору. Суммарный объём обработки приближался к квадратичному по числу движений: для очередного документа повторно просматривалась значительная часть месячного набора.

Вот почему в 1-й декаде мая среднее проведение выписки занимало 358 миллисекунд, во 2-й — 304, в 3-й — 249. К концу месяца проведение ускорялось, потому что после документа оставалось меньше движений. Зависимость от даты была не случайностью календаря, а тенью квадрата — и эту тень мы увидели.

Зачем киту этот запрос

Оставался вопрос: зачем типовой алгоритм запрашивал остаток, если результат не менял проводок?

У поступлений по основному договору эквайринга проводка — Дт 51 Кт 57.03. В расшифровке платежа — автоматическое погашение задолженности. Счёт расчётов совпадает со счётом авансов. Аналитика по документам расчётов отсутствует. Типовой алгоритм получает остаток и делит платёж на погашение задолженности и аванс. Но обе части записываются на 1 счёт с одинаковыми субконто. После свёртки проводок суммы по счетам и аналитике совпадают.

Запрос определял разбиение суммы на строки, но после свёртки результат не менялся. Это была работа ради работы — гребца, который машет веслом в воздухе.

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

Течения и мели

Вениамин проверил и типовой механизм отложенного проведения — настройку «Расчёты выполняются при закрытии месяца». При нём расчёты с контрагентами выполняются пакетом по договорам, вместо запроса задолженности при проведении каждого платёжного документа. Доступность механизма проверяет функция ПроведениеСервер.ИспользуетсяОтложенноеПроведение. В нашей базе проверка возвращала Ложь — потому что используется ФИФО, а требуется оценка по средней. Менять учётную политику ради ускорения перепроведения мы не стали.

Отдельно он проверил отключение текущих итогов регистра Хозрасчетный. Строки текущих итогов составляли около 1,9% от числа строк периодических итогов. При отключённом флаге темп вырос с 46,7 до 54,3 фиксации в секунду — примерно на 16%. Время дорогого запроса сократилось со 138 до 50–57 миллисекунд. Но обратное включение требовало пересчёта, который занимал 35 минут. Порог окупаемости — около 3 ч 40 мин непрерывного перепроведения. Для 1 месяца приём не окупался.

Глава III. Разработчик

3-м на борт поднялся Корнилий, разработчик расширений для 1С. Он был моложе нас обоих и говорил быстрее, чем думал, — но думал он быстро. Он не любил долгих объяснений. «Я знаю, где болит, — сказал он, выслушав Вениамина. — Теперь скажите, куда бить».

И он выковал 2 гарпуна.

1-й гарпун: «Оптимум»

«Оптимум» — расширение, которое исключает из запроса строки платежа, для которых остаток не нужен. Корнилий изменил функцию УчетВзаиморасчетов.ПодготовитьТаблицуВзаиморасчетовПогашениеЗадолженности. Перед вызовом ПолучитьОстаткиЗадолженности расширение отбирает строки расшифровки:

Строка исключается, только если выполнены одновременно все условия:

• направление операции — поступление, не возврат;

• организация не применяет УСН и патент;

• нет учёта по подразделениям;

• расчёты ведутся в рублях;

• счёт расчётов — 57.03;

• счёт расчётов совпадает со счётом авансов;

• отсутствует субконто «Документы расчётов».

Разрешён только счёт 57.03: для него разобран алгоритм и проверены движения. Если после отбора строк не осталось — запрос не выполняется, блокировка регистра не устанавливается. Для изменения используется &ИзменениеИКонтроль: при обновлении конфигурации можно обнаружить изменение заимствованной функции.

2-й гарпун: «Независимость»

«Независимость» — расширение, которое исключает часть уже проведённых поступлений из повторного проведения. Идея Корнилия была проста: если поступление по эквайрингу без комиссии банка, с проводками только Дт 51 Кт 57.03, и суммы проводок задаются самим документом, то повторное проведение не требуется для пересчёта себестоимости или распределения платежа. Типовой алгоритм всё равно устанавливает состояние «проведён с нарушением последовательности», и при следующем закрытии обработка возвращается к этому участку.

Расширение проверяет:

• вид операции — поступление по платёжным картам;

• комиссия банка отсутствует в шапке и строках расшифровки;

• все проводки активны и имеют корреспонденцию Дт 51 Кт 57.03;

• сумма проводок совпадает с суммой документа;

• прежняя версия документа удовлетворяет проверке;

• дата документа не перенесена вперёд;

• имеется 1 запись последовательности с состоянием «проведён в последовательности».

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

Куда гарпун не бьет

Корнилий оговорил ограничения. Отмена проведения и пометка удаления обрабатываются типовым кодом. Поступления с комиссией банка из перепроведения не исключаются. Если изменились настройки счетов или аналитики 57.03 и требуется заново сформировать движения — нужно использовать самостоятельную обработку «Групповое перепроведение», а не помощник закрытия. Условия 2 расширений различаются: «Оптимум» сохраняет самостоятельное применение при загрузке новых поступлений, проведении выписок с комиссией и принудительном полном перепроведении.

Глава IV. Результат

Три ночи Вениамин и Корнилий провели у сервера. Базу готовили, как корабль к отплытию: перед каждым запуском последовательность нарушали одним и тем же документом. Для серии использовали 2-й сервер — 4 ядра, 31 ГБ памяти, synchronous_commit = off. Сервер приложений 1С оставался прежним. Условия серии существенны: приведённое время нельзя переносить на другой сервер или на закрытие при работающих пользователях.

Полный май

Применение двух расширений ускорило перепроведение вдвое. Среднее время документа снизилось с 277 до 192 миллисекунд с 1 «Оптимумом», а количество перепроводимых документов сократилось с 40 000 до 22 000.

Расширение «Оптимум» не изменило количество перепроводимых документов — 40 398. Но среднее время выписки упало с 300 до 121 миллисекунды. По декадам стало практически одинаковым: 118, 121, 122. Зависимость от даты исчезла вместе с запросом остатков. Доля поступлений на расчётный счёт сократилась с 53 до 31% времени перепроведения.

Регламентные операции после перепроведения с одним «Оптимумом» выполнились за 79 секунд. С двумя расширениями — за 71 секунду. Ошибок не было.

Сверка

Результат проверяли по снимкам движений: для каждой пары «регистр — регистратор» сохраняли число строк и хэш содержимого. Выполняли два сравнения: исходных строк и проводок после свёртки.

Построчное совпадение получили не везде. На стенде за июль отличались 6 пар из 11 047 — 3 выписки, в которых типовой код разделял платёж на 2 строки с одинаковой аналитикой, а расширение записывало одну строку. После свёртки различий не осталось. Для мая сверка охватила 212 регистров, 41 817 регистраторов и 178 089 пар. После свёртки различий не было.

Суммы по счетам и субконто сохранились. Количество строк проводок у отдельных выписок изменилось — это нужно учитывать при проверке обработок и отчётов, которые работают с отдельными строками движений.

Одна выписка в закрытом море

Отдельно проверили рабочий случай: месяц закрыт, пользователь повторно проводит 1 выписку начала месяца. Взяли поступление по эквайрингу от 2 мая. Расширение записало в журнал причину: комиссии нет, проводки только Дт 51 Кт 57.03, прежняя версия также удовлетворяет проверке. Повторный запуск закрытия занял около 4 секунд. Фоновое задание не запускалось, документы не перепроводились, регламентные операции не пересчитывались. Все 39 186 записей последовательности сохранили состояние «проведён в последовательности». В снимках различий по 178 089 парам не было.

4 секунды вместо 3 часов. Это был не ещё 1 вариант ускорения — это был конец охоты.

Глава V. Как мы мерили

Каждый источник решал свою задачу.

Журнал регистрации дал состав обработанных документов и время завершения. pg_stat_statements — общее время SQL: до и после прогона снимали накопленные показатели только по исследуемой базе. pg_stat_database — прирост xact_commit для оценки темпа. Технологический журнал — события DBPOSTGRS от 20 миллисекунд, TLOCK от 1 секунды, TTIMEOUT, TDEADLOCK, EXCP. Свойство Context вело от SQL к месту вызова в конфигурации. Планы дорогих запросов получали через auto_explain.

Снимки движений проверяли число строк и хэш содержимого. При отличиях сравнивали проводки после свёртки.

Вениамин отмечал несколько особенностей прогона. Рабочее множество rphost росло около 17 минут — для сравнения установившегося темпа брали участки после первых 20. Начало и конец месяца неоднородны по стоимости — сравнивали одинаковые периоды. 1-е и повторное закрытие различаются: в рабочей базе 1-е закрытие меняло движения примерно у 19% документов и занимало примерно на 10% больше времени. Показатели времени СУБД из разных источников имеют разный смысл: на 1 прогоне получили 32% по сумме времени SQL, 44% по опросу pg_stat_activity и 53% по duration‑all‑dbms из rac. Сравнивать нужно по 1 методике.

Обслуживание

В описанной серии обслуживание не было главной причиной, но на соседних базах встретились случаи, которые стоит учитывать. После восстановления базы запрос остатков выполнялся за 7,5 секунды. Пробный ANALYZE 2 таблиц сократил время до 1,9 миллисекунд. Порог autovacuum_analyze_scale_factor = 0,05 оказался слишком большим — снизили до 0,01. Добавили ночной ANALYZE с отбором таблиц по n_mod_since_analyze.

Необходимость перестройки индексов проверяли через pgstattuple. Расчёт по системному каталогу показал предполагаемое разрастание 36–39% у 3 индексов таблицы итогов. Измеренная плотность около 65% не стала основанием для перестройки. Для таблиц крупнее 10 млн строк использовали autovacuum_vacuum_scale_factor = 0,005.

Пересчёт итогов во время работы пользователей привёл к управляемой блокировке на 15 минут. 12 непроведённых банковских документов, 10 — по причине блокировки. В pg_stat_activity картины не было: конфликт возник на уровне 1С. После этого пересчёт выполняли фоновым заданием в согласованное технологическое окно.

Глава VI. Что проверять при внедрении

Если кто‑то захочет повторить этот путь в другой базе, прежде всего нужно подтвердить распределение времени. Если основную часть закрытия занимают реализации с ФИФО, а поступлений по эквайрингу мало — описанные изменения не дадут сопоставимого результата.

Порядок был таким:

• Устранить ошибки проведения документов исследуемого периода и проверить учётную политику.

• Зафиксировать релиз конфигурации, платформу, настройки СУБД и условия запуска.

• Снять исходное время перепроведения и регламентных операций, состав документов, статистику СУБД и снимки движений.

• Проверить применение перехватов расширений по журналу регистрации.

• Повторить обработку того же периода в сопоставимых условиях.

• Сравнить длительность, количество проведённых документов, движения и состояние последовательности.

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

• После завершения снять дополнительное журналирование и проверить необходимость обновления статистики таблиц.

Для ночного запуска нужно оставлять время до резервного копирования и других регламентных заданий. После прерванного закрытия следует проверить состояние регламентных операций: они могли оставаться в состоянии «Выполняется» до следующего успешного завершения.

Эпилог

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

Исключение этого запроса сократило время полного перепроведения мая с 3 ч 06 мин до 2 ч 09 мин. Исключение подходящих уже проведённых поступлений из повторной обработки дополнительно сократило его до 1 ч 32 мин. Для сценария с повторным проведением одной выписки закрытого месяца удалось сохранить последовательность: повторный запуск завершился примерно за 4 секунды без перепроведения документов.

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

Разработку и замеры выполняли на БП 3.0.206.19. При обновлении конфигурации необходимо повторно проверить изменяемую функцию и условия применения расширений. Приходные кассовые ордера розничной выручки, списания и оплаты картой остаются кандидатами для дальнейшего исследования.

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