Всем привет, меня зовут Миша, и я разрабатываю платформу Яндекс Еды. Первые компоненты были написаны почти 10 лет назад (когда Еда ещё была стартапом Foodfox), и у нас накопилось много кода, который просто хорошо работает, а иногда даже «работает — не трогай». Но в процессе развития и устоявшиеся части системы нужно трогать, про что мои коллеги уже писали — как мы повышали версию PHP, пилили монолит и снимали нагрузку с БД.

Наконец настал черёд рассказать про процессинг заказов доставки еды из кафе и ресторанов (а также продуктов из магазинов и многого другого). За годы эволюционного развития он значительно разросся, что стало заметно затруднять дальнейшее развитие — например, изменения, связанные с выходом на новые рынки, — а также влиять на надёжность.

Поэтому мы решили вынести процессинг заказа в отдельный специализированный сервис. Чтобы определить, что выносить, а что оставлять, нужно было составить исчерпывающий и актуальный список процессов, которые происходят с заказом. И здесь мы столкнулись с вызовом: это знание распределено по многим людям и документам, поскольку на протяжении долгого времени в процессинг заказов вносили изменения многие команды. И перед нами встал вопрос — как собрать нужную информацию о системе с заметной долей легаси быстро, да так, чтобы информация была актуальна?

Как выглядит наш процессинг: схема и жизнь

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

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

В чём сложность выноса процессинга

Как обычно, сложности в деталях.

1. Предметная область сложнее, чем кажется:

   • На схеме показаны три основных пути заказа, но тонких параметров заметно больше.

   • Много источников информации о статусах заказа: разные API партнёров, логистика, собственное приложение для ресторанов и так далее.

   • В зависимости от параметров заказа одни и те же переходы между статусами запускают разные процессы.

2. Монолит в процессе расселения:

   • Команды выносят свои участки в микросервисы, но старый код остаётся — где‑то отключён флагами, где‑то просто не вызывается, где‑то дублирует работу.

   • Иногда в монолите появляется новая функциональность для процессов, которые ещё не успели вынести.

3. Нельзя просто так взять и прочитать весь код:

   • Всего 1,5 миллиона строк PHP‑кода и 30 тысяч классов.

   • Из 1500 эндпоинтов и воркеров каждый пятый связан с заказами.

   • Код местами запутанный, с асинхронными вызовами самого себя и обильным использованием событий.

4. Наивные подходы не работают:

   • Опросить десяток смежных команд — долго и ненадёжно, коллеги могут упустить какие‑то детали.

   • Читать код — его так много, что код может устареть за время изучения.

Поэтому пришлось подойти совсем с другой стороны.

Общий ход решения

Верный вопрос

Искать другой путь мы начали с того, что ещё раз сформулировали задачу и цель, на пути к которой она стоит.

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

Первые идеи — читать код, опрашивать коллег — наводили тоску и уныние, и задача казалось совершенно нерешаемой в нужные сроки и с требуемой надёжностью. А что делает инженер, когда сталкивается с нерешаемой задачей? Правильно, обращается к таблице объёмов красных резиновых мячей методам решения нерешаемых задач, то есть, проще говоря, изобретает.

На новый путь меня навели некоторые идеи из ТРИЗ — несмотря на то, что ТРИЗ в целом создавалась для решения задач, так сказать, материальной инженерии, многие приёмы успешно распространяются и на виртуальную. Альтшуллер (создатель ТРИЗ) предлагает начинать решение всех изобретательских задач так: найти противоречие, усилить его и сформулировать идеальный конечный результат.

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

Такое нереалистичное усложнение задачи сразу отметает всякие компромиссные идеи, и остаётся только один путь — монолит каким‑то образом должен сам «рассказывать» о тех процессах, которые в нём происходят с заказом.

Система сама показывает, что в ней происходит с заказом — хорошая основа для формулирования идеального конечного результата. Не хватает только одного: а как это «показывает» должно выглядеть?

Как выглядит «мы понимаем, что происходит»

Так же, как и на предыдущем шаге, сначала представим себе идеальный результат. Как выглядит идеальное представление процессов? Здесь ничего изобретать не нужно, а достаточно вспомнить, что есть блок‑схемы, диаграммы последовательности и прочие устоявшиеся способы визуального представления.

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

Осталось понять только одно: а что за элементы должны отображаться на блок‑схеме? Что по природе своей должны представлять шаги, из которых состоит процесс?

Если мы никак не можем разобраться во внутреннем устройстве (а в наших усложнённых условиях это невозможно: нет ни людей, ни документации), то нам остаётся подходить к нему, как к чёрному ящику. А всё, что мы можем легко узнать про чёрный ящик, — это то, что происходит на его границах: входящие и исходящие сигналы.

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

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

А в журнале событий мы будем находить процессы с помощью техники Process Mining.

Как построить Process Mining

Process Mining в первую очередь направлен на анализ бизнес‑процессов. На Хабре время от времени про это пишут, да и других материалов в сети достаточно, поэтому ограничусь кратким описанием.

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

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

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

Общий план аналитической части таков:

• Выгрузить журнал событий.

• Понять, что именно мы хотим видеть на схеме.

• Визуализация и анализ.

• …

• PROFIT!

Подготовка журнала событий

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

1. Запись заказа в базу и чтение его оттуда.

2. Входящие HTTP‑запросы и ответы на них.

3. Исходящие HTTP‑запросы и ответы на них.

4. Постановка задачи в очередь и взятие задачи в работу.

Здесь, разумеется, нас интересуют не вообще все HTTP‑запросы и не все задачи в очереди, а только те, что каким‑то образом относятся к заказу. Поскольку заказы в Яндекс Еде имеют характерный вид номера (например, 250 523–14 973 563), то найти эти строки в данных и атрибутировать происходящее конкретным заказом не составляет труда.

Трейсинг — наше всё

В идеальном мире вся эта информация уже есть в виде трейсов. В идеальных трейсах есть всё необходимое: и номер заказа в виде тега, и что именно происходит, и какой запрос куда ушёл и тому подобное. К сожалению, идеальных трейсов у нас нет (хотя работа над этим ведётся). А особенно нет их в монолите: например, вся работа воркера очереди записывается в один трейс (каждый спан соответствует отдельной задаче). И конечно же, далеко не каждому спану вообще проставлялся номер заказа, а это — ключевой момент.

Это связано с тем, что для Городских сервисов Яндекса наш едовый монолит — это несколько чужеродный элемент. Те удобные инфраструктурные интеграции, которые предоставляет наша технологическая платформа для сервисов на C++, Python и Go, на PHP приходилось реализовывать самостоятельно.

Поэтому вместо того, чтобы долго и мучительно наводить порядок в трейсинге монолита через OpenTelemery, а потом так же долго выяснять, как же выудить из обилия трейсов нужные нам события, мы решили сделать маленькое и очень специализированное решение. На него ушёл целый один рабочий день.

И как раз PHP и фреймворк Symfony помогли нам в итоге очень быстро разработать отдельное решение. Symfony почти везде поддерживает механизм слушателей событий, и практически весь трейсинг уложился в один класс, подписанный на нужные события (HTTP‑запросы к монолиту и работа с БД на встроенных в Symfony событиях, работа с очередями на наших событиях). В базовом классе HTTP‑клиента добавилась одна middleware, которая искала в первых килобайтах запроса или ответа что‑то, напоминающее номер заказа, и этим покрыты исходящие HTTP‑запросы и ответы на них. Разумеется, регистрацию каждого вида событий можно включать и выключать отдельно.

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

• время (само пишется в лог);

• номер заказа;

• тип события;

• тип контекста: эндпоинт, очередь или консольная команда, запускаемая по крону;

• имя контекста (эндпоинта, очереди или команды).

Для части операций мы можем записать дополнительную важную информацию.

• При операциях с БД:

  • статус заказа;

  • тип заказа и тип его обработки.

• Для HTTP‑запросов:

  • для входящих — сервис‑источник;

  • для исходящих — сервис‑назначение, хост, путь и метод.

public function onRequest(RequestEvent $event): void
{
    try {
        $request = $event->getRequest();

        $route = $request->attributes->get('_route', '__unknown__');
        $this->orderTracer->setContext(OrderTraceContextTypeEnum::ROUTE_HANDLER, $route);

        $this->detectSource($event);

        if ($this->orderTracer->isEnabled(OrderTraceAspectEnum::HTTP_REQUEST)) {
            $this->traceRequest($event);
        }
    } catch (\Throwable $e) {
        $this->logger->warning('Trace subscriber error', [
            'method' => 'onRequest',
            'exception' => $e,
        ]);
    }
}


public function traceRequest(RequestEvent $event): void
{
    try {
        $request = $event->getRequest();
        $params = $request->attributes->all();
        foreach ($params as $key => $value) {
            if ($orderNr = $this->matchOrderNr($value)) {
                $this->orderTracer->trace(new OrderTraceDto(
                    $orderNr,
                    null,
                    OrderTraceAspectEnum::HTTP_REQUEST,
                    ['param' => $key]
                ));
                break;
            }
        }
    } catch (\Throwable $e) {
        $this->logger->warning('Trace subscriber error', [
            'method' => 'traceRequest',
            'exception' => $e,
        ]);
    }
}

Запись в логе выглядит приблизительно так:

# номер заказа, к которому относится событие
order_nr: "240704-04322656"
# в каком контексте оно произошло
context_type: "route"
context: "api_v1_order_version_list"
# кто пришёл в эту ручку
source: "partner-integrations"
# какое событие произошло
aspect: "http_client_request"
# детали события
method: "POST"
host: "order-versions.eda.yandex"
path: "/v1/versions/find"

Утка спешит на помощь

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

Но какие именно из этих данных нам нужны, сначала было непонятно. Выгрузка в формате csv, дополнительно сжатая gzip, заняла около 17 Гб. Это действительно много безусловно полезной информации, но как экспериментировать с таким объёмом данных?

Коллеги советовали мне поднять локальную инсталляцию PostgreSQL, куда положить разобранные логи, я скорее думал про ClickHouse или ClickHouse Local, поскольку колоночные базы подходят для подобных данных, как правило, лучше. Но здесь возникла другая проблема: я собирался использовать богатый инструментарий из экосистемы bupaverse, и хранилище для локальных экспериментов должно было отвечать следующим требованиям:

• возможность локально и быстро производить произвольные операции над большим логом;

• хорошая интеграция с R и tidyverse.

PostgreSQL не удовлетворяет первому требованию, ClickHouse — второму. Сначала я пытался использовать data.table, но несмотря на компактное и эффективное представление данных в памяти, её всё равно не хватало. Тогда я обнаружил DuckDB, и все проблемы были решены.

Во‑первых, DuckDB может просто загрузить файл .tsv.gz в свою базу данных, не распаковывая его. БД выросла в полтора раза по сравнению с исходным файлом, зато на все столбцы были созданы min‑max‑индексы.

Во‑вторых, на таких объёмах данных DuckDB по производительности самых разных запросов на одном уровне с ClickHouse

В‑третьих, с помощью dbplyr к табличке в базе DuckDB можно обращаться так же, как к обычному дата‑фрейму. Обычно это не требует вообще никаких изменений в коде.

В‑четвёртых, DuckDB может многое делать в памяти, но при этом почти все операции могут прозрачно сбрасывать промежуточные результаты на диск — поэтому для обработки данных мне вполне хватало 32 Гб оперативной памяти.

Вместо тысячи слов:

CREATE TABLE logs AS SELECT * FROM read_csv_auto('~/prod_order_trace.tsv.gz')

Проба пера

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

con <- dbConnect(duckdb(dbdir = "~/trace.db"))
con %>% tbl('logs') %>%
  filter(aspect %in% c('doctrine_load', 'doctrine_save')) %>%
  group_by(orderNr, status) %>%
  summarise(timestamp = min(timestamp)) -> db_events
Получилось около 8 млн событий, и теперь их нужно превратить в eventlog:
db_events %>% 
  mutate(lid=1) %>%
  bupaR::eventlog(case_id='orderNr',
                  resource_id='orderNr',
                  activity_id=c('status'),
                  activity_instance_id = c('orderNr', 'status'),
                  timestamp = 'timestamp',
                  lifecycle_id='lid'
  ) -> evlog

(если вы не поняли, что здесь происходит, отсылаю к моей предыдущей статье про R)

Как видно, bupaR довольно жёстко требует создать структуру данных, ориентированную на бизнес‑процессы (значение всех полей расписано в документации). Некоторые из них можно было бы использовать по назначению, но в итоге это оказалось ненужным.

Осталось построить из этого журнала событий карту процессов:

evlog %>% processmapR::process_map(rankdir='TB')

На выходе в окошке просмотра мы сразу получаем (относительно) красивый граф статусов и переходов между ними. На сырых данных он выглядит примерно вот так:

Хоть на этой схеме и виден основной путь следования заказа и он даже совпадает с начальной схемой, здесь видна одна проблема: трейсы по заказам могут начинаться не сначала и заканчиваться не на самом конце. Большая часть заказов, сюда попавших, вообще уже доставлены (это видно по толщине стрелки). Поэтому данные нужно каким‑то образом отфильтровать.

Предварительная обработка данных

Отсекаем головы и хвосты

Теперь из почти полумиллиарда строк нужно оставить только полезные строки. Первое, что я сделал, — отделил головы и хвосты, то есть заказы, не вся история по которым попала в выгрузку за сутки. Логика простая: выбираем все логи, где создаётся заказ (на чекауте), а также находим все логи по финальным статусам заказа.

CREATE TABLE good_orders AS 
SELECT started.orderNr FROM (
  SELECT orderNr FROM logs
  WHERE context LIKE 'order_checkout%'
  GROUP BY orderNr) started -- заказ начинается на чекауте
INNER JOIN (
  SELECT orderNr FROM logs
  WHERE status in ('cancelled', 'delivered')
  GROUP BY orderNr) ended -- и заканчивается в одном из финальных статусов
ON (started.orderNr = ended.orderNr);

Около 900 тыс. «полных» заказов было выбрано за 4,4 секунды из почти 4 млн упомянутых в логе (COUNT DISTINCT посчитался за 3,9 секунды). Я специально привожу время исполнения запросов, чтобы подчеркнуть, что у меня была возможность экспериментировать с запросами без какого‑либо существенного ожидания результатов.

Потом я создал VIEW, в котором остались данные только по полным заказам:

CREATE VIEW logs_good AS
SELECT * FROM logs
INNER JOIN good_orders USING (orderNr)

и на этом моя работа с сырым SQL закончилась следующим образом:

library(tidyverse)
library(duckdb)
library(DBI)
library(dbplyr)

con <- dbConnect(duckdb(dbdir = "~/trace.db"))
ldata <- con %>% tbl('logs_good')

Посмотрим, помогла ли фильтрация

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

evlog %>% 
  processmapR::process_map(
    rankdir='TB',
    layout = processmapR::layout_pm(edge_weight=T))

Happy path стал выглядеть на схеме гораздо лучше. А если исключить рёбра, встречающиеся реже, чем в 0,1% случаев (например, переход из «отмены» и «подтверждён» невозможен, и это несовершенство сбора данных, связанное с транзакциями и репликацией), то картина становится практически такой, как мы рисовали руками в начале:

Здесь даже видны все три способа доставки: переход «приготовлен → доставлен» — это самовывоз, а «в пути → доставлен» — это заказы с доставкой партнёра: у них нет отдельного статуса «прибыл к клиенту» до доставки. Также со схемы пропали редкие отмены заказов со статуса «в пути».

Немодифицирующий запрос? Давай, до свидания!

Следующие данные, которые обильно присутствовали в логах, но при этом не несли почти никакой полезной информации, — трейсы немодифицирующих запросов, которые ничего не меняли, а просто отдавали какую‑то информацию какому‑то сервису. Чтобы выявить степень зависимости таких сервисов от монолита, хватало простой аналитики с тремя колонками: эндпоинт, запрашивающий сервис, RPS, и небольшой беседы с мейнтейнерами (а иногда просто чтения кода сервиса).

В общем, немодифицирующие запросы — как входящие, так и исходящие — следует исключить из анализа. По конвенциям REST API запрос с методом GET не может быть модифицирующим, и это правило, к счастью, в коде соблюдается без исключений.

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

./bin/console --no-debug debug:route --format=json

Далее превратить их в дата‑фрейм:

jsonlite::read_json('routes.json') %>% 
  enframe() %>% 
  unnest_wider(value)  %>%
  hoist(defaults, controller=c('_controller')) %>%
  select(name, method, host, path, controller) -> route

И получить список контекстов для исключения:

routes %>%
  filter(method == 'GET') %>%
  pull(name) -> contexts_exclude

В процессе обнаружилось следующее: REST‑конвенция, конечно, запрещает GET‑запросам быть модифицирующими, но она не обязывает быть модифицирующими все POST‑запросы. Поэтому список роутов пришлось ещё немного проредить. Я взял самые частые роуты по логам и сразу присоединил к ним табличку с роутами, чтобы было легко смотреть в код, если понадобится:

ldata %>%
  filter(context_type == 'route', !context %in% contexts_exclude) %>%
  count(context, sort=T) %>%
  as_tibble() %>%
  left_join(routes, join_by(context == name))

SELECT context, COUNT(*) AS n
FROM (
  SELECT logs_good.*
  FROM logs_good
  WHERE (context_type = 'route') AND (NOT(context IN ...))
) q01
GROUP BY context
ORDER BY n DESC

Несколько минут изучения таблички — и десяток частых немодифицирующих POST‑запросов ушли в список исключаемых.

С исходящими немодифицирующими запросами всё оказалось сложнее. GET‑запросы можно так же легко выкинуть, а вот как найти POST‑запросы в смежные сервисы, которые на самом деле не модифицируют данные, и интереса для анализа не представляют? Не читать же, право, весь код 30+ сервисов, с которыми есть связь.

Но здесь снова пригодился список гарантированно немодифицирующих GET‑запросов, тот самый contexts_exclude. Если известно, что этот запрос не модифицирует данные, то и все запросы к другим сервисам, отправляемые в его рамках, также данные не модифицируют. Бинго!

ldata %>%
  filter(
         # внутри тех эндпоинтов, которые в чёрном списке
         context_type == 'route',
         context %in% contexts_exclude,
         # все действия типа http-запрос
         aspect %in% c('http_client_request')) %>%
  distinct(host, path) -> safe_requests

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

ldata %>%
  filter(!context %in% contexts_exclude) %>%
  anti_join(safe_client_requests, join_by(host, path))

SELECT LHS.*
FROM (
  SELECT logs_good.*
  FROM logs_good
  WHERE NOT(context IN (...))
) LHS
WHERE NOT EXISTS (
  SELECT 1 FROM (
  SELECT host, path, COUNT(*) AS n
  FROM (
    SELECT logs_good.*
    FROM logs_good
    WHERE
      (context_type = 'route') AND
      (context IN (...)) AND
      (aspect IN ('http_client_request'))
  ) q01
  GROUP BY host, path
) RHS
  WHERE (LHS.host = RHS.host) AND (LHS.path = RHS.path)
)

Лучше меньше, да лучше

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

ldata %>% 
  group_by(orderNr) %>% 
  select(orderNr, flow_type, order_type) %>%
  filter(across(everything(), ~ !is.na(.))) %>%
  summarise(across(everything(), first))

SELECT orderNr, FIRST(flow_type) AS flow_type, FIRST(order_type) AS order_type
FROM (
  SELECT orderNr, flow_type, order_type
  FROM logs_good
  WHERE (NOT((flow_type IS NULL))) AND (NOT((order_type IS NULL)))
) q01
GROUP BY orderNr

И дальше остаётся сгруппировать по всем параметрам, исключая номер заказа, и выбрать по 5000 случайных заказов из каждой группы:

... %>%
  group_by(across(!orderNr)) %>% 
  slice_sample(n=5000) %>%
  pull(orderNr) -> orders.sample

Кстати, на момент анализа я сначала выгрузил все данные в табличку в R, а затем уже семплировал данные из неё. Но при написании статьи я проверил — благодаря dbplyr это так же просто превращается в один SQL‑запрос (я просто убрал вызов as_tibble из середины конструкции) и работает на 10–15% быстрее за счёт меньшего копирования данных в памяти, хотя абсолютная разница в примерно одну секунду тут не особенно ощутима.

SELECT orderNr, flow_type, order_type
FROM (
  SELECT
    q01.*,
    ROW_NUMBER() OVER (PARTITION BY flow_type, order_type ORDER BY RANDOM()) AS col01
  FROM (
    SELECT
      orderNr,
      FIRST(flow_type) AS flow_type,
      FIRST(order_type) AS order_type
    FROM (
      SELECT orderNr, flow_type, order_type
      FROM logs_good
      WHERE (NOT((flow_type IS NULL))) AND (NOT((order_type IS NULL)))
    ) q01
    GROUP BY orderNr
  ) q01
) q01
WHERE (col01 <= 5000)

И далее с помощью уже приведённого выше запроса выгружаю, наконец, нужные данные в R для последнего шага обработки.

ldata %>%
  filter(orderNr %in% orders.sample) %>%
  filter(!context %in% contexts_exclude) %>%
  anti_join(safe_requests, join_by(host, path)) %>%
  as_tibble() -> logs

Феерическое заполнение пропущенных данных

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

Первая версия заполнителя данных выглядела совсем просто:

  logs %>%
    arrange(timestamp) %>%
    group_by(orderNr) %>%
    fill(flow_type:order_type, status, .direction = 'downup')

Но у неё были проблемы с транзакционностью и с моделью данных в Symfony. Сортировка логов по времени перемешивала данные, и в результате появлялись ошибки такого типа:

В контексте Y заказ, уже загруженный из БД, не поменяет свой статус без повторной загрузки и будет отправлен в сервис как «созданный», а заполнение последним непустым значением посчитает, что он был отправлен как «оплачен».

Эту проблему я осознал далеко не сразу, а только когда увидел странные вещи, которые никогда не должны были происходить (например, отправка уведомления типа «заказ готов» для уже отменённого заказа). Финальная версия этого шага выглядит так:

logs %>%
  # вычисляем универсальный run_id для очередей и эндпоинтов
  mutate(run_id = coalesce(queue_run_id, request_id)) %>%
  arrange(timestamp) %>%
  group_by(orderNr) %>%
  # заполняем поля с типами
  fill(flow_type:order_type, .direction = 'updown') %>%
  # группируем по run_id, заполняя статусы внутри одного контекста
  group_by(orderNr, run_id) %>%
  fill(status, .direction = 'downup') %>%
  # наконец, заполняем остальные статусы заказов «вниз»
  group_by(orderNr) %>%
  fill(status, .direction = 'down') -> logs.filled

Как построить карту процессов

Не пытаться объять необъятное

Теперь, наконец, наши данные готовы к построению карты процессов, которая выглядит примерно так:

На этой карте я вывел топ-100 встречающихся контекстов по частоте, чтобы получить «общую картину».

logs %>%
  filter(!action %in% c('doctrine_load', 'http_client_response', 'http_client_request')) %>%
  filter(!context %in% contexts_exclude) %>%
  bupaR::eventlog(
            case_id = 'orderNr',
            	resource_id='orderNr',
            	activity_id=c('status', 'context_type', 'context'),
            	activity_instance_id = c('orderNr', 'status', 'context'),
            	timestamp = 'timestamp',
            	lifecycle_id='lid',
            	validate = F
) -> events

events %>% 
  count(status_context_type_context, sort=T) %>% 
  head(n=100) %>%
  pull(status_context_type_context) -> top_g

events %>%
  filter(status_context_type_context %in% top_g) %>%
  processmapR::process_map(rankdir = 'TB', render=F) -> graph

graph %>% DiagrammeR::generate_dot() %>% write_file('chaos.dot')

Когда я посмотрел на эту схему, то во мне закралась мысль: не проще ли читать код, чем разбираться в этом? Но это можно упростить и разделить несколькими разными способами.

Во‑первых, мы уже знаем, что разные типы заказов обрабатываются немного по‑разному и мы можем взять только один тип обработки. На деле это не очень помогло, потому что заметная часть критичных процессов для разных видов общая, а строить полдюжины схем, а потом искать на них различия — то ещё удовольствие.

Во‑вторых, мы можем разделить весь процессинг заказа на крупные этапы. Например, строить схему не целиком, а только для тех контекстов, в которых заказ был в каком‑то определённом статусе. Например, если мы выберем все контексты, где заказ был «доставлен», то мы удачно захватим и сам переход заказа в этот статус, и всё, что происходит после этого. Заодно выкинем редкие кейсы другим способом:

events %>%
  filter(target_status %in% status, .by='run_id') %>%
  # фильтруем только те заказы, у которых встречался нужный статус
  filter((orderNr %in% orderNr[status == target_status]), .by='run_id') %>%
  # убираем совсем редкие события
  filter(n() > (nrow(.) * 0.001), .by='context_type_context')  %>%
  processmapR::process_map(rankdir='TB', render=F)

Эта схема выглядит, как бы это сказать, несколько лучше:

Но на этой схеме у нас отображены только одни контексты, а нас‑то интересуют действия внутри контекстов:

events %>%
  bupaR::eventlog(activity_id=c('context_type', 'context', 'action')) %>%
  filter(n() > (nrow(.) * 0.001), .by='context_type_context_action')  %>% 
  processmapR::process_map(rankdir='TB', render=F)

И тут снова всё становится плохо:

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

%>% filter('partner-integrations' %in% source, .by='orderNr') %>%

И — о чудо! — картинка становится обозримой!

Продолжаем разделять и властвовать

Внимательный читатель наверняка уже заметил на предыдущей схеме вот этот фрагмент:

В нём queue_reciept_sender_queue_consumer происходит, кажется, между двумя любыми событиями «основного пути».

Так и есть. Надпись queue_reciept_sender_queue_consumer мы мысленно делим на три части:

• queue — тип контекста;

• reciept_sender — наименование очереди;

• queue_consumer — взятие задачи в работу.

В начале «основного» пути (по толстым стрелкам) мы действительно видим постановку задачи в эту очередь (route — тип контекста, order_event — имя роута, reciept_sender — имя очереди). Логично, что задача, поставленная в очередь, может быть взята в работу с разной задержкой в зависимости от массы разных обстоятельств, и это порождает множество лишних стрелок на схеме.

Дело в том, что карта процессов через processmapR не слишком хорошо подходит для того, чтобы отображать несколько параллельных процессов. Для этого в экосистеме bupaverse есть альтернативное решение: heuristicsmineR. Он пытается оценить, насколько часто события идут в определённом порядке, и на основании этого может более или менее успешно разделять параллельные процессы.

С использованием эвристического майнинга картина выглядит заметно лучше и понятнее:

events %>%
  filter(target_status %in% status, .by='run_id') %>%
  filter((orderNr %in% orderNr[status == target_status]), .by='run_id') %>%
  filter(n() > (nrow(.) * 0.001), .by='context_type_context') %>%
  heuristicsmineR::causal_net(threshold_frequency=.3) %>%
  heuristicsmineR::render_causal_net(rankdir='TB')

Заодно я сделал дополнительную обработку надписей на графе так, чтобы разделять три составные части имени.

logs %>%
  bupaR::eventlog(activity_id=c('context_type', 'context', 'action')) %>%
  filter('partners-integration' %in% source, .by='orderNr') %>%
  filter(n() > (nrow(.) * 0.001), .by='context_type_context_action') %>%
  # параметр threshold_frequency подобран экспериментально :))
  heuristicsmineR::causal_net(threshold_frequency=.3) %>%
  heuristicsmineR::render_causal_net(rankdir='TB', render=F) -> cnet
  
activities <- logs %>%
  group_by(action, context_type, context, true_label=str_c(context_type, context, action, sep='_')) %>%
  summarise()

cnet$nodes_df %>%
  separate_wider_delim(label, "\n", names=c('true_label', 'count'), too_few='align_start', cols_remove = F) %>%
  left_join(activities, join_by(true_label)) %>%
  mutate(
    label = if_else(is.na(context), label, glue::glue("{context_type}: {context}\n{action}")),
  ) -> fixed

cnet$nodes_df$label <- fixed$label
cnet$edges_df$label <- NA

DiagrammeR::render_graph(cnet)

И, наконец, последний штрих: объединяем в кластеры те действия, которые относятся к одному контексту, присваивая в nodes_df значения полю cluster.

Мы настолько упростили схему, что один из фильтров — по источнику информации о том, что заказ доставлен, — можно убрать:

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

Ещё кейсы

Вся эта машинерия по анализу заказа укладывается в 191 строчку кода на R и примерно 90 строк комментариев, в которых подробно описано, как загрузить данные, как пользоваться скриптом и т. д. И это не запутанный код, в котором максимум конструкций утрамбованы в одну строку, а простой и читаемый — собственно, примеры выше были взяты оттуда (и слегка адаптированы). Одна строка — одно действие, за редким исключением.

Для сравнения: трейсер, собирающий исходные данные на PHP, занимает 255 строк кода. Правда, на его написание и отладку ушёл примерно один рабочий день, а на анализатор — почти неделя, хотя первые результаты появились уже на второй день работы.

Собственно, схемы, которые появляются на выходе — это и есть почти то, что нужно. Со схемой не нужно больше искать, где именно происходит какое‑то действие: на схеме есть имя роута или очереди. Коллеги из других команд больше не должны вспоминать, что происходит, по схеме можно задать конкретный вопрос: «В этом эндпоинте монолит ходит в такой‑то эндпоинт вашего сервиса. Это бизнес‑критичный процесс?»

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

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

Точно знаем, кто, как двигает заказы, и какие именно

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

ldata %>%
  group_by(orderNr) %>%
  filter(status==target_status, aspect=='doctrine_save') %>%
  summarise(timestamp = min(timestamp)) %>%
  left_join(con %>% tbl('logs')) %>%
  count(context_type, context, source, flow_type, order_type) %>%
  as_tibble() -> first_status_appears

В этой табличке — первая запись, где появляется избранный статус для каждого заказа. Так мы узнаём, где именно статус изменился на этот.

first_status_appears %>%
  # группируем по всему, кроме source
  group_by(across(!source)) %>%
  # клеим source, если туда ходят несколько источников
  summarise(source=str_c(source, collapse = ', '), n = sum(n)) %>%
  # строим сводную таблицу
  pivot_wider(
	# это будущие заголовки строк
	id_cols=c(context_type, context, source),
	# будущие столбцы
	names_from = c(flow_type),
	# будущие значения
	values_from = n,
	# и как их агрегируем
	values_fn=sum
  ) %>%
  # total -- сумма всех чисел в строке
  rowwise() %>% 
  mutate(total=sum(pick(where(is.numeric)), na.rm = T)) %>%
  # сортируем и смотрим
  arrange(-total) %>% View

Итоговая табличка выглядит приблизительно так (я выкинул часть столбцов и округлил цифры):

С этими табличками связан забавный случай: построив такую таблицу, я ходил к мейнтейнерам каждого сервиса и выяснял, как и почему именно они присылают в процессинг этот статус. И однажды в ответ на свой вопрос «В каких конкретно случаях происходит вот такое вот изменение?» я получил вопрос: «А разве мы так делаем?». Но мы быстро разобрались, что всё‑таки делаем, и выяснили, в каком именно случае.

Разобрались с логистическими очередями за полчаса

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

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

evlog %>% 
  filter(context_type == 'queue', str_detect(context, 'delivery_')) %>%
  bupaR::eventlog(activity_id='context') -> logistics_events

logistics_events %>%
  heuristicsmineR::causal_net(threshold = .8, threshold_frequency = .3) %>%
  heuristicsmineR::render_causal_net(rankdir='LR', render=F) %>% 
  {
    .$nodes_df$label %<>% str_replace(regex("(delivery)_"), "\\1_\n")
    .
  } %>%
  DiagrammeR::render_graph()

И получил следующую картину:

Разговор стал куда более предметным: нашлась забытая очередь, которая обновляет планируемое время прибытия курьера в ресторан, — а это важно, чтобы блюдо не приготовили слишком рано и оно не успело остыть.

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

Стало быть, любую стенку можно так убрать?

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

Как начать

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

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

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

Экспериментировать быстро

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

Здесь стек R + DuckDB + dbplyr показывает себя очень эффективно: благодаря удобству dbplyr можно легко писать самые разные запросы и переиспользовать почти весь написанный код, а DuckDB обеспечивает быстроту их исполнения в большинстве случаев.

В качестве альтернативы можно также использовать data.table: он намного быстрее стандартных дата‑фреймов и по производительности не уступает DuckDB, но требует более внимательного подхода и синтаксис там несколько сложнее (хотя есть обёртка dtplyr, превращающая глаголы dplyr в операции data.table).

Что показать

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

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

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

Так открывается перспектива с помощью одной и той же технологии получать детальное описание какого‑либо процесса практически с подробностью логов или же строить общую схему системы так, как мы рисуем это на собеседованиях по system design — и всё это исключительно на основе данных.

Вместо заключения

Разбирать легаси‑код гораздо приятнее, когда у тебя есть карта процессов, а не просто код, разрозненная документация и рассказы коллег. Чтобы построить её, не нужно погружаться подробно в каждый модуль или сервис, и анализ событий на границах «чёрных ящиков» может дать достаточно информации для того, чтобы понимать, куда именно смотреть и о чём именно спрашивать. «Выкопанные» из системы процессы избавляют от львиной доли скучного рутинного разбора кода и позволяют как легко видеть общую картину, так и погружаться в детали при необходимости.

Но, честно говоря, закончить статью я хотел бы мыслями совсем другого плана. И трейсинг, и process mining — технологии давно известные и обкатанные, а такой технический анализ процессов в большой системе — лишь удачное их сочетание. Тем не менее задача, к которой даже не было понятно, с какой стороны подойти, решена быстро и эффективно.

Но как же находить хотя бы такие удачные сочетания? Элементы ТРИЗ, кажется, неплохо подходят на эту роль. Меня всегда удивляло, что из «типовых приёмов» некоторые сформулированы максимально обобщённо (например, принцип дробления или принцип динамичности), в то время как другие очень «физичны» (применение сильных окислителей). Принципы первой группы часто подходят для решения задач и программной инженерии, а какое‑нибудь «применение сильных окислителей» совершенно неприменимо к разработке (если только не посчитать это в шутку метафорой «перепишите всё на Rust»).

Ещё один способ, которым я пользовался для поиска решения, заимствован — внезапно! — из феноменологической философии Эдмунда Гуссерля, из той части, которую Даниил Разеев удачно назвал «археологией очевидности». Что это вообще означает и как этим пользоваться? Главный вопрос, который я себе часто задавал на протяжении анализа, — «а как именно я это понял?». Например, а как именно я понимаю, что я описал все процессы? А как я понимаю, что это процесс, когда его вижу? В общем, останавливаться на том, что кажется и так понятным, и рефлексировать на тему того, как я прихожу к этой очевидности.

Из методологических приёмов я ещё вспоминаю о «парадоксе изобретателя»: иногда сложные задачи можно сделать проще, если их правильно обобщить. Можно сказать, что вместо задачи разбора конкретного монолита была решена задача анализа процессов в любом «чёрном ящике». Но правильное обобщение здесь как раз помог найти ТРИЗ‑процесс обострения конфликта.

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