История поиска проблемы, которая происходит раз в 1000 лет07.11.2021 22:16

Как сейчас помню, понедельник 25е октября, я заступаю на дежурство по проду и с самого утра мне прилетает задача: сегодня в ночь с 24 на 25 ноября, наблюдалась проблема с недоступностью приложения. Глянув сентри я увидел кучу ошибок от базы со statement timeout, а так же непонятные ActiveRecord::ConnectionNotEstablished: No connection pool with 'primary' found. С мыслью «база не отвечала, проблема не на нашей стороне» я спокойно отдал задачу на разбирательство админам, а сам параллельно глянул графики, может там был всплеск каких-нибудь джобок или запросов, но ничего криминального в графане небыло: тяжеловесных джобок в 12 не запускается, а те, что запускаются отработали очень быстро.

Спустя недолгое время пришел первый звоночек. Для его объяснения дам небольшую вводную: наше приложение использует трех разных пользователей для подключения к БД: один для сайдкика, второй для апп сервера, третий для выполнения миграций. Настройки у них отличаются statement timeout’ом: для апп сервера он совсем маленький, для демонов чуть побольше, ну, а для пользователя под которым запускаются миграции он вовсе отсутствует. Так вот, в 12 часов ночи резко выросло количество подключений под юзером migrations.

c51694518c6239306e1910f53157166a.jpg

Я сразу вспомнил, что в 12 часов у нас стартуют джобы на создание партиций для наших партиционированных таблиц: 

round_partitions_job:
  cron: '0 0 25 * *'  # At 00:00 on day-of-month 25
  class: RoundPartitionsJob
processed_events_partitions_job:
  cron: '0 0 25 * *'  # At 00:00 on day-of-month 25
  class: ProcessedEventsPartitionsJob
user_balance_changes_partition_job:
  cron: '0 0 25 * *'  # At 00:00 on day-of-month 25
  class: UserBalanceChangesPartitionJob

Хмм, в самом начале эти джобы подключаются к базе под пользователем migrations и создают партиции. Но эти таблицы никак между собой не связаны, конфликтов быть не должно. Однако то, как они подключаются вызывает вопросы: 

Rails.root.join("config", "database.migrations.yml")
      .yield_self(&File.method(:read))
      .yield_self { |f| ERB.new(f).result }
      .yield_self(&YAML.method(:load))
      .dig(Rails.env)
      .yield_self(&ActiveRecord::Base.method(:establish_connection))

Стало понятно почему у нас резко выросло кол-во подключений под migrations пользователем. Вместо того, чтобы создать новое подключение к базе мы переподключали ActiveRecord: Base.connection. Таким образом процесс, который выполнял джобку на создание партиций переставал работать под своим обычным пользователем и продолжал работать под migrations юзером, что могло вызвать затупы при выполнении длинных запросов. В принципе это уже серьезный косяк, который нужно поправить. Но что-то не сходилось: приложение таймаутило только 15 минут, а по графику migrations пользователь работал с полуночи до 12 дня. Значит проблема не в этом. Или не только в этом, думаем дальше.

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

[vxid:80/29134748 txid:0] [idle in transaction] LOG: statement: CREATE TABLE rounds_2021_11 PARTITION OF rounds FOR VALUES FROM (‘2021-11-01 00:00:00’) TO (‘2021-12-01 00:00:00’);

Хммм, забавно, ведь создание партиции это очень простая операция, которая не требует каких-то длинных блокировок и не совсем понятно почему этот запрос (и несколько других в той же транзакции) упали в iddle in transaction. Что ж, настало время грепать логи. 

2021-10-25T00:00:00.080Z class=RoundPartitionsJob INFO: start  
# ... кучка логов
2021-10-25T00:00:00.090Z DEBUG: (0.5ms)  BEGIN (0.3ms)  
2021-10-25T00:00:00.093Z DEBUG: (0.3ms) SHOW statement_timeout; 
2021-10-25T00:00:00.099Z DEBUG: (4.6ms) SET LOCAL statement_timeout = '0'; 
2021-10-25T00:00:00.184Z DEBUG: (86.4ms) CREATE TABLE rounds_2022_11 PARTITION OF rounds FOR VALUES FROM ('2021-11-01 00:00:00') TO ('2021-12-01 00:00:00'); 
2021-10-25T00:00:00.191Z DEBUG: (5.5ms) CREATE INDEX ... ON rounds_2021_11 ...;           
                                        CREATE INDEX ... ON rounds_2021_11 ...;           
                                        CREATE INDEX ... ON rounds_2021_11 ...;  
2021-10-25T00:00:00.201Z ERROR: ActiveRecord::ConnectionNotEstablished: No connection pool with 'primary' found.
2021-10-25T00:00:00.208Z DEBUG: (2.3ms) ROLLBACK
# ... кучка логов

Ага, вот вижу ошибку, в принципе она самая первая в истории. Все остальные таймауты продолжали сыпаться уже после 2021–10–25T00:00:00.191Z. В целом ActiveRecord: ConnectionNotEstablished говорит о том, что рельса не смогла выбрать конект из пула. НО КАК? Ведь видно же, что без проблем создали партицию, конект был, куда он мог пропасть?! Продолжаю грепать дальше. Все остальные джобы на создание партиций отработали без проблем. Далее из логов базы было видно что все запросы которые пытаюстя взять хоть какой-то лок на таблицу rounds падают по таймауту, а т.к. эта таблица активно используется проектом это и создает все таймауты, которые наблюдают пользователи. Однако я четко вижу ролбэк, который рельса послала после того как была зарейзена ошибка, никаких локов быть не должно. И еще вопрос: если нету конекта, то куда мы послали ролбэк и почему эта проблема появилась только сейчас, код работает уже пару лет? вопросы все интересней, понятнее не становится.

После гуглежа у меня появляется мысль: если 2 джобы, которые создают партиции стартуют в одно время и попадают на один сервер и в один процесс, то это может создать проблемы с конектами. Грепаем еще раз и бинго! 

2021-10-25T00:00:00.162Z pid=106112 tid=7cdk class=UserBalanceChangesPartitionJob jid=ee3fe50224a09f0580880f97 INFO: start
2021-10-25T00:00:00.080Z pid=106112 tid=28ykc class=RoundPartitionsJob jid=7cc286bcc428205c53ec17e1 INFO: start

Именно это и произошло, pid’ы одинаковые. У нас 3 сервера для демонов, на кажом сервере запущено по 10 процессов сайдкика, в каждом процессе по 7 тредов. И нам очень повезло что 2 крон джобки попали в один процесс. Далее моя гипотеза такая (однако воспроизвести проблему еще раз мне не удалось):

  1. в 2021–10–25T00:00:00.080Z стартует RoundPartitionsJob, которая устанавливает конект под migrations юзером

  2. RoundPartitionsJob создает партиции, проблем нету

  3. 2021–10–25T00:00:00.162Z стартует UserBalanceChangesPartitionJob, которая начинает устанавливать еще один конект под migrations юзером

  4. между 2021–10–25T00:00:00.162Z и 2021–10–25T00:00:00.191Z рельса находится в каком-то половинчатом состоянии, т.к. RoundPartitionsJob не смог взять конект из пула, то UserBalanceChangesPartitionJob уже отрубил старый конект, но не создал новый, RoundPartitionsJob падает

  5. между 2021–10–25T00:00:00.191Z и 2021–10–25T00:00:00.208Z UserBalanceChangesPartitionJob уже корректно установила конект, рельса шлет ROLLBACK под новым конектом, поэтому этот ролбэк уходит в пустоту, таблица rounds не освобождает лок, все тормозит

Если глянуть на код рельсы то моя теория подтверждается: 

def establish_connection(config)
  resolver = ConnectionSpecification::Resolver.new(Base.configurations)
  spec = resolver.spec(config)

  remove_connection(spec.name) # тут конекта нету

  message_bus = ActiveSupport::Notifications.instrumenter
  payload = {
    connection_id: object_id
  }
  if spec
    payload[:spec_name] = spec.name
    payload[:config] = spec.config
  end

  # и только тут он появляется
  message_bus.instrument("!connection.active_record", payload) do
    owner_to_pool[spec.name] = ConnectionAdapters::ConnectionPool.new(spec)
  end

  owner_to_pool[spec.name]
end

Между 7й и 17й строкой рельса еще не успела установить новый конект и если произойдет переключение тредов то мы без проблем можем попасть в состояние без активный подключений к базе. Однако есть один нюанс: когда рельса делает remove_connection(spec.name) она делает disconnect на текущем конекте и тогда активная транзакция должна автоматом ролбэчнутся. Каким-то образом этого не произошло (или я чего-то не понимаю) и таблица rounds так и осталось залоченой, для меня это до сих пор загадка. Но через 15 мин лок все-таки снялся, джоба по созданию партиции заретраилась и создала партицию, все таймауты ушли.

Решение

Когда проблема понятна пофиксить ее не составляет проблем. До Rails версии 6.0 можно использовать это решение, но т.к. мы уже успели обновиться решили использовать стандартный механизм рельсы и обернуть создание партиций в 

ApplicationRecord.connected_to(role: :migration) do
  # create partitions
end

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

© Habrahabr.ru