company_banner

Приключения одного бага или как починить pgx чужими руками

    Привет, меня зовут Иван, и я делаю Авито Доставку.


    Тестирую я как-то раз один из наших сервисов на быстродействие. И в метриках pgbouncer’a вижу вот такую печальную картину:


    метрики pgbouncer'а
    Зелёный — число активных клиентских соединений (cl_active), красные точки — число клиентских соединений, которым не досталось серверного соединения (cl_waiting, правая шкала)


    Расследуя этот график, удалось выйти на занятный баг, снять блокер по переезду на четвёртую версию pgx, а также немного разобраться в устройстве pgx и pgbouncer’a.


    Чем же так печальна эта картина


    На графиках видно, что по мере роста нагрузки растёт число активных соединений и достигает ограничения в 10 штук — тут всё логично. Но дальше с ростом нагрузки cl_active неожиданно падает, а число cl_waiting быстро растёт почти до 60. Как сервис умудрился создать 60 соединений, если размер его пула — 10? Заметим, что сервис при этом заваливается и почти никакой полезной работы не выполняет:


    нагрузочный тест
    Сверху — входная нагрузка в RPS, посередине — время отклика в миллисекундах по перцентилям, внизу — число успешных и неуспешных ответов


    Устройство сервиса


    диаграмма
    Стрелки показывают, кто о ком «знает»


    Сервис на Go развёрнут в k8s, в нескольких небольших подах. PostgreSQL развёрнута в LXC контейнере, рядом с ней живёт pgbouncer.


    Всё очень просто: на входе HTTP-запрос, сервис формирует SQL-запрос, шлёт его в базу, затем сериализует результат и отвечает пользователю. Основная работа происходит в базе, она же является узким местом по производительности.


    Сервис подключается к pgbouncer с помощью pgx/v4. Пул клиентских соединений ограничен со стороны сервиса (до 10) и со стороны pgbouncer (до 100 по умолчанию). Между pgbouncer и базой тоже свой пул в 10 серверных соединений.


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


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


    LSR-1223: лёг item-storage.

    Куча 500-х ошибок.

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

    В item-storage обновили pgx на четвёртую версию, где нельзя отключить cancelContext.

    Страшная вещь эти архивы. И полезная. У нас, похоже, происходит то же самое: растёт нагрузка, начинаются отмены запросов, создаются соединения на их отмену и забивают пул pgbouncer. Размер пула у нас 100. Максимум мы видели ~60 соединений, но это, скорее всего, неточность метрики, ведь она снимается всего лишь дважды в минуту.


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


    отмена чужого запроса в pgbouncer


    «Postgres выполнит команду и отменит текущий запрос в заданном процессе. Но текущим запросом будет уже не тот, который мы хотели отменить изначально. Из-за такого поведения при работе с Postgres вместе с PgBouncer безопаснее будет не отменять запрос на уровне драйвера. Для этого можно задать функцию CustomCancel, которая не будет отменять запрос, даже если используется context.Context


    А вот здесь просят @jackc, автора pgx, вернуть в четвёртую версию CustomCancel, который позволяет запретить отмену. Мотивируют, опять же, опасностью отменить не тот запрос:


    Джек, верни CustomCancel


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


    Джек отказывается


    Соответственно, вернуть CustomCancel он отказался до появления тест-кейса.


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


    • форкнуть pgx;
    • форкнуть pgbouncer;
    • написать демон, перезапускающий pgbouncer при переполнении пула.

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


    Отмена запросов в PostgreSQL и pgbouncer


    Как вообще происходит отмена запросов в PostgreSQL?


    Каждому соединению PostgreSQL выдаёт уникальный cancel_key. Чтобы отменить запрос, нужно создать новое соединение со специальным стартовым сообщением (CancelRequest вместо StartupMessage) и отправить в него cancel_key от соединения, на котором исполняется запрос. Подробнее — в документации.


    Pgbouncer знает о концепции отмены запросов. Создавая соединение к базе, он запоминает выданный Постгресом cancel_key, но не отдаёт его клиенту. Вместо этого для каждого клиентского соединения он сам генерирует уникальный cancel_key:


    /* give each client its own cancel key */
    get_random_bytes(client->cancel_key, 8);

    То есть клиент знает cancel_key от соединения к pgbouncer, но не знает cancel_key от соединения к базе, и не может его отменить. Когда клиент пытается отменить запрос, он посылает pgbouncer’у cancel_key от клиентского соединения. Если это соединение в данный момент подключено к серверному, то есть активно, то pgbouncer возьмёт cancel_key от серверного соединения и отменит запрос в нём по стандартной процедуре:


    /* remember server key */
    server = main_client->link;
    memcpy(req->cancel_key, server->cancel_key, 8);
    
    /* attach to target pool */
    req->pool = pool;
    change_client_state(req, CL_CANCEL);
    
    /* need fresh connection */
    launch_new_connection(pool);

    Если же клиентское соединение неактивно, pgbouncer просто проигнорирует запрос на отмену и закроет клиентское соединение:


    /* not linked client, just drop it then */
    if (!main_client->link) {
      /* ... */
    
      disconnect_client(req, false, "cancel request for idle client");
    
      return;
    }

    Похоже, всё-таки отменить чужой запрос при работе через pgbouncer невозможно, что и объясняет, почему @jackc не смог этого добиться в своём тесте.


    Остается ещё один вариант отменить не тот запрос, который хотели. Представим ситуацию:


    1. Посылаем запрос.
    2. Пытаемся его отменить.
    3. Пока запрос на отмену добирается до базы, исходный запрос успевает завершиться, и соединение освобождается.
    4. Посылаем в то же соединение второй запрос.
    5. В этот момент до базы добирается запрос на отмену, убивая второй запрос.

    Отменить запрос в чужом соединении так не получится: мы не знаем cancel_key от него. А своё соединение нам подконтрольно. Мы всегда знаем, какой запрос хотим отменить, и можем не посылать новые запросы в это же соединение (шаг 4). Кстати, pgx/v4 так и делает: при отмене запроса pgx всегда закрывает соединение.


    Выходит, отменять запросы в связке pgx/v4 + pgbouncer + PostgreSQL можно. Но проблема остаётся: пул соединений переполняется. Чтобы найти причину, нужно заглянуть в pgx.


    Отмена запросов и управление пулом в pgx/v4


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


    • Pgconn отвечает за низкоуровневое управление соединением. Именно она заведует отменой запросов и знает всё про протокол Постгреса. А вот про пул соединений она не знает ничего.
    • Pgxpool отвечает за управление пулом соединений. Делает она это на уровне пула объектов PgConn из библиотеки pgconn. Про отмену запросов она ничего не знает, а если случится таймаут, просто «уничтожает» объект PgConn.

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


    1. Закрывается контекст (context.Context).
    2. Происходит ошибка соединения.
    3. Объект PgConn уничтожается и при этом запускает асинхронную отмену запроса.
    4. Pgxpool видит, что в пуле освободилось место, и создаёт новый PgConn, который, в свою очередь, создаёт новое соединение.
    5. «Уничтоженный» PgConn тоже создаёт соединение, чтобы отменить запрос. А своё основное соединение он закроет только после отмены. При этом про ограничение на размер пула он не знает и создаёт соединения сверх лимита.

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


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


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


    Обработка отмены контекста в pgx


    Pgx обрабатывает отмену контекста довольно хитро. Вместо того чтобы везде делать select:


    select {
    case <-ctx.Done():
    //...
    }

    она создаёт объект, наблюдающий за отменой запроса:


    pgConn.contextWatcher = ctxwatch.NewContextWatcher(
      func() { pgConn.conn.SetDeadline(time.Date(1, 1, 1, 1, 1, 1, 1, time.UTC)) },
      func() { pgConn.conn.SetDeadline(time.Time{}) },
    )

    Внутри этот объект создаёт горутину, которая делает обычный select, а при отмене контекста вызывает коллбек и устанавливает давно пропущенный дедлайн прямо на нижележащем соединении net.Conn:


    pgConn.conn.SetDeadline(time.Date(1, 1, 1, 1, 1, 1, 1, time.UTC))

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


    n, err := pgConn.conn.Write(buf)
    if err != nil {
      pgConn.asyncClose()
      return &writeError{err: err, safeToRetry: n == 0}
    }

    При закрытии контекста Write() немедленно вернёт ошибку. Решение с select было бы куда более многословным.


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


    Тест-кейс для @jackc


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


    Тест-кейс на это может быть простым: будем обстреливать базу из нескольких воркеров, посылая запросы, которые всегда отменяются. Замерять будем число соединений на pgbouncer’е. Наша цель — превысить лимит пула сервиса, а ещё лучше, забить пул соединений pgbouncer.


    Нам потребуется три докер контейнера: сервис, обстреливающий базу, pgbouncer и Postgres. Урезанный docker-compose.yml (полная версия):


    services:
      web:
        build: .
      pgbouncer:
        image: pgbouncer/pgbouncer
      postgres:
        image: postgres

    В сервисе всё тоже просто. Создадим 100 воркеров, обстреливающих базу в цикле:


    ctx, cancel := context.WithTimeout(ctx, 10 * time.Millisecond)
    defer cancel()
    
    q := `select pg_sleep(10)`
    rows, _ := db.Query(ctx, q)
    defer rows.Close()

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


    Метрики снимаем с помощью команды show pools pgbouncer’а:


    echo "show pools;" | psql -h localhost -p 6432 -U postgres pgbouncer

    Получаем такой результат:


    • cl_active: 2
    • cl_waiting: 97
    • sv_login: 1
    • активных серверных соединений — ни одного

    Пул соединений сервиса у нас ограничен до 10, пул pgbouncer — до 100. Видим, что весь пул pgbouncer’а забит, практически никакой полезной работы база не делает.


    Всё плохо. То есть хорошо, ведь мы же этого и хотели. Пора идти к Джеку.


    Фикс


    Джек, увидев наши находки, смог подтвердить проблему и ответил очень быстро. И сразу предложил простое и элегантное решение.


    Он ввёл синхронизацию (diff) между pgxpool и pgconn. Теперь pgxpool ждёт, пока pgconn отменит запрос и закроет соединение. И только потом создается новый объект PgConn и новое соединение.


    Организовано это с помощью канала PgConn.CleanupDone(). PgConn его закрывает, уведомляя pgxpool о том, что место в пуле действительно освободилось.


    Прогон тест-кейса подтвердил, что число соединений остаётся в пределах размера пула сервиса:


    • cl_active: 1
    • cl_waiting: 8

    Обновляем pgx в сервисе до пропатченной версии, нагружаем:


    нагрузочный тест
    Входная нагрузка в RPS, время отклика в мс, число ответов


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


    метрики pgbouncer
    cl_active держится на уровне 24 (это максимальный размер пула сервиса), cl_waiting не появляется


    Если подать на сервис нагрузку вдвое больше максимальной, то cl_waiting появляются:


    метрики pgbouncer


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


    Теперь можно переезжать на 4 версию pgx, обходные решения не понадобятся. Если работаете с pgx под нагрузкой, вас это тоже касается.


    TL;DR, или выводы


    1. Сняли блокер по переезду на pgx/v4 для Авито, да и для всех, кто использует pgx под нагрузкой. До релиза фикса использовать pgx/v4 вместе с pgxpool — опасно.
    2. Отменять SQL-запросы при работе через pgbouncer — можно.
    3. Правильно подобранные аргументы могут многое.

    UPD: Как верно подметили в комментариях, проблема решена для связки pgx/v4+pgxpool, а в варианте pgx/v4+database/sql она все еще проявляется. Поэтому не стоит использовать pgx четвертой версии в режиме совместимости с database/sql. Обсуждение здесь. Что с этим делать, пока не вполне понятно.


    Благодарности


    Екатерине Семеновой — за LSR’ы и системную работу с инцидентами.


    Джеку Кристенсену — за оперативное исправление бага.


    Анне Лесных и Дмитрию Назаркову — за помощь в подготовке статьи.

    Авито
    У нас живут ваши объявления

    Комментарии 14

      +1
      Сняли блокер по переезду на pgx/v4 для Авито, да и для всех, кто использует pgx под нагрузкой.

      На сколько я понимаю, проблема воспроизводится только при использовании pgxpool. Если использовать pgx со стандартным database/sql, то проблемы нет. Поэтому приведеная выше фраза не совсем корректная.

      А вообще очень интересная история, спасибо, и молодцы что донесли до апстрима!
        0
        Я не проверял, но, пожалуй, соглашусь. Поправлю.

        Спасибо!
          +1
          Попробовал погонять тесты из этой статьи на pgx 4.8.2 с database/sql и у меня получилось воспроизвести проблему: cl_waiting в 100, cl_active и sv_active по 0. Я не смотрел как устроен стандартный пуллер, но что-то мне подсказывает, что он не знает и никогда не узнает о фиксе, который придумал Джек.
            0

            И даже понятно, почему: пулер database/sql не ждет, пока PgConn закроет свои коннекты

        –1

        Слушайте. А кто-то вообще планы запросов строил? Нагрузку тестировал? Почему время ответа базы растет?
        Данные кто и как моделировал? За ростом индексов кто то следит?
        Из прочитанного мне вилится, что рабоиа с бд для вас черный ящик. Иначе провели бы работы по оптимизации базы, а не клиентского ПО

          +2
          Слушаю) Про запрос и нагрузочное тестирование будет в следующей статье. И то, наверное, оптимизацию запроса придется опустить, т.к. материала много. Но план запроса будет. Эта же статья посвящена починке конкретного бага, который мешал нагрузить базу как следует. Вопросов оптимизации статья не касается.

          За моделирование данных, подбор индексов, за оптимизацию запросов у нас отвечает разработчик сервиса. Он при этом плотно взаимодействует с DBA, использует их экспертизу.
          +1
          А зачем вы используете (пул соединений в) pgbouncer, если у вас в приложении (pgx) есть свой пул соединений?
          Вроде, при использовании pgbouncer, теряется часть функционала, связанная с соединением (подготовленные операторы, курсоры, асинхронные уведомления, ...)
            0
            В один баунсер обычно ходит много инстансов приложения — и они друг про друга и лимиты соседей ничего не знают.
              0

              Хороший вопрос. Непосредственные причины, по которым у нас появился pgbouncer, не назову: это было до меня. Думаю, дело вот в чем:


              Можно работать и без connection pooler'а, но это требует от сервиса жесткой дисциплины:


              • Нельзя делать долгие транзакции; недопустимо оставлять незакрытые транзакции
              • Нужно всегда четко следить за размером пула

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


              Кроме того, база в LXC контейнере — это относительно новая конфигурация для Авито. Большинство сервисов работает с базами на "коммуналках" — базы делят один сервер. Ограничивать потребление ресурсов конкретной базой там непросто; основной способ — ограничение размера пула. ДБА хотят это явно контролировать, а не перекладывать на разработчиков.


              В общем, хорошему сервису pgbouncer практически не мешает. А плохому не дает наделать глупостей и позволяет удовлетворительно работать. Как-то так.


              Кстати, вот хорошая статья об этих проблемах https://brandur.org/postgres-connections

              +3
              Килл происходит через отдельные соединения, и из-за этого все коннекты в баунсере заполнились и новые перестали проходить.

              В качестве решений, в частности, предлагалось

              Вот тут вам еще предлагали использовать odyssey вместо pgbouncer — https://github.com/pgbouncer/pgbouncer/issues/392#issuecomment-645998318
              там это пофикшено: https://github.com/yandex/odyssey/issues/84


              Мы тоже испытывали боли с pgbouncer и cancel request, и решили их комплексно...


              Проверить испытывает ли ворклоад проблему с cancel request можно через метрику:
              https://www.pgbouncer.org/usage.html#show-lists
              если used_clients > cl_active, значит в cancel_req_list копится очередь из cancel.


              Есть так же другая проблема, которую не видно на метриках pgbouncer/postgres, бывает такое что под большой нагрузкой код начинает слишком часто отменять запросы и поскольку каждый cancel это новый коннект, то здесь (https://i.imgur.com/8Q0UbeC.png) уже втыкаемся в ограничения на стороне куба


              заканчиваются эфемерные порты, которых по умолчанию 30к

              диагностировать такое можно, например, так:


              $ zcat pgbouncer.log-*.gz |fgrep 'cancel' | grep -o '2020-08-21 [0-9][0-9]:[0-9][0-9]' | sort |uniq -c
              
                15617 2020-08-21 07:52
                19656 2020-08-21 07:53
                19306 2020-08-21 07:54
                19616 2020-08-21 07:55
                15222 2020-08-21 07:56
                   77 2020-08-21 07:57
                   64 2020-08-21 07:58
                   81 2020-08-21 07:59
                   87 2020-08-21 08:00
                 4515 2020-08-21 08:01
                17948 2020-08-21 08:02
                17027 2020-08-21 08:03
                16986 2020-08-21 08:04
                17215 2020-08-21 08:05
                16577 2020-08-21 08:06
                17108 2020-08-21 08:07
                17152 2020-08-21 08:08
                16881 2020-08-21 08:09
                16968 2020-08-21 08:10
                16258 2020-08-21 08:11
                15627 2020-08-21 08:12
                16722 2020-08-21 08:13
                15944 2020-08-21 08:14
                18246 2020-08-21 08:15
                  235 2020-08-21 08:16
                   74 2020-08-21 08:17
                   64 2020-08-21 08:18
                   59 2020-08-21 08:19
                   54 2020-08-21 08:20
                18644 2020-08-21 08:21
                16323 2020-08-21 08:22
                17491 2020-08-21 08:23
                17019 2020-08-21 08:24
                16435 2020-08-21 08:25
                16644 2020-08-21 08:26
                17450 2020-08-21 08:27
                17468 2020-08-21 08:28
                16731 2020-08-21 08:29
                 6502 2020-08-21 08:30

              но поскольку 30к это довольно не мало и сервисов, которые столько раз синхронно ходят в postgres немного, то встречается гораздо реже, чем subj, но имеет место быть. Надеюсь кому-нибудь будет полезна эта инфа.

                0

                Тут проблема была все-таки не в pgbouncer'е, а в pgx, так что замена на odyssey, возможно, и не помогла бы. Ну, и odyssey пока не в стеке компании; его использование пришлось бы долго обосновывать.


                За подсветку проблемы с коннектами на поде — спасибо, полезно!


                Мы тоже испытывали боли с pgbouncer и cancel request, и решили их комплексно...

                А как решили, если не секрет?

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

              Самое читаемое