Как отладить приложение rails, когда ошибка возникает только на производстве?

Question

Итак, мое веб-приложение rails размещено на Heroku, и я получаю ошибку H12 от Heroku, означающую, что на выполнение запроса уходит более 30 секунд.В процессе разработки, запрос также занимает очень много времени, чтобы полностью выполнить, но в конце концов работает.Поэтому я не получаю никакой ошибки в режиме разработки.

Я получаю подсказку о том, в чем проблема, когда я просматриваю логи:

SubscriptionOrder Load (19.4ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  SubscriptionOrder Load (0.7ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 AND "subscription_orders"."running" = $3 ORDER BY "subscription_orders"."id" DESC LIMIT $4  [["user_id", 107], ["state", "paid"], ["running", "t"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
   (4.4ms)  SELECT COUNT(*) FROM "orders" WHERE (user_id = 107 AND (status = '') IS NOT FALSE AND created_at >= '2018-09-17 10:00:38.559259')
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 AND "subscription_orders"."running" = $3 ORDER BY "subscription_orders"."id" DESC LIMIT $4  [["user_id", 107], ["state", "paid"], ["running", "t"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
   (0.6ms)  SELECT COUNT(*) FROM "orders" WHERE (user_id = 107 AND (status = '') IS NOT FALSE AND created_at >= '2018-09-17 10:00:38')
   (1.4ms)  SELECT COUNT(*) FROM "free_meals" WHERE (used = 'f' AND user_id = 107)
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  Subscription Load (0.4ms)  SELECT  "subscriptions".* FROM "subscriptions" WHERE "subscriptions"."id" = $1 LIMIT $2  [["id", 6], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 AND "subscription_orders"."running" = $3 ORDER BY "subscription_orders"."id" DESC LIMIT $4  [["user_id", 107], ["state", "paid"], ["running", "t"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE  (0.0ms)  SELECT COUNT(*) FROM "orders" WHERE (user_id = 107 AND (status = '') IS NOT FALSE AND created_at >= '2018-09-17 10:00:38.559259')
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 AND "subscription_orders"."running" = $3 ORDER BY "subscription_orders"."id" DESC LIMIT $4  [["user_id", 107], ["state", "paid"], ["running", "t"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE  (0.0ms)  SELECT COUNT(*) FROM "orders" WHERE (user_id = 107 AND (status = '') IS NOT FALSE AND created_at >= '2018-09-17 10:00:38')
  CACHE  (0.0ms)  SELECT COUNT(*) FROM "free_meals" WHERE (used = 'f' AND user_id = 107)
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE Subscription Load (0.0ms)  SELECT  "subscriptions".* FROM "subscriptions" WHERE "subscriptions"."id" = $1 LIMIT $2  [["id", 6], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 AND "subscription_orders"."running" = $3 ORDER BY "subscription_orders"."id" DESC LIMIT $4  [["user_id", 107], ["state", "paid"], ["running", "t"], ["LIMIT", 1]]
  CACHE SubscriptionOrder Load (0.0ms)  SELECT  "subscription_orders".* FROM "subscription_orders" WHERE "subscription_orders"."user_id" = $1 AND "subscription_orders"."state" = $2 ORDER BY "subscription_orders"."id" DESC LIMIT $3  [["user_id", 107], ["state", "paid"], ["LIMIT", 1]]
  CACHE  (0.0ms)  SELECT COUNT(*) FROM "orders" WHERE (user_id = 107 AND (status = '') IS NOT FALSE AND created_at >= '2018-09-17 10:00:38.559259')

... и так далее, и так далее.Запрос БД SubscriptionOrder выполняется 100 раз.

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

Answer 1

Это похоже на N + 1 проблему.Вы просматриваете каждого пользователя и отображаете их заказы на подписку, но каждый раз делаете SQL-запрос.

Это означает много SQL-запросов, что приводит к увеличению времени загрузки.Как правило, это означает, что вам придется указывать Rails загружать объединенную модель в одном запросе SQL, а не при первом ее вызове.Метод включает позволит вам сделать это.

Добавление bullet gem в ваше приложение поможет вам обнаружить эти проблемы N + 1 и исправить их.