Измеряй, затем действуй

Сегодня мне напомнили о важности измерения, а не предположений.

Я подумал, что напишу пост, пройдясь по нему — так хоть что-то полезное может получиться, если кому-то еще поможет.

Задний план

Последние пару дней я пытался улучшить скорость тестового бега. Это было нормально для начала, но чем больше тестов я добавлял, тем дольше выполнялись прогоны. Когда дошло до того, что в некоторых разделах каждый тест занимал 600–1300 мс, мне это надоело, и я решил что-то с этим сделать.

Отправная точка

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

В инструкциях на этой странице сказано, что --prof включит профилирование узла. Я хотел получить результаты профиля от запуска Mocha, а не «просто» Node. Добавление флага как --v8-prof означает, что Mocha передаст флаг в Node:

$ NODE_ENV=test mocha --v8-prof --require test/fixtures.js
$ node --prof-process isolate-0x102d57000-8614-v8.log > processed.txt

К сожалению, там не обнаружилось ничего очевидного, но точки входа в C++ подтвердили теорию баз данных.

[C++ entry points]:
   ticks    cpp   total   name
   3497   72.1%   58.8%  T __ZN2v88internal21Builtin_HandleApiCallEiPmPNS0_7IsolateE
   1290   26.6%   21.7%  T

72% в HandleApiCall — единственные вызовы API, которые мы делаем, — это обращение к базе данных, так что это хорошее место для начала.

Погоня за дикими гусями

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

  • Я потратил время на тестирование перехода от knex-cleaner к удалению объектов по отдельности с помощью knex("table").del().
  • Многие тесты повторно засеивают все, и я тратил время, пытаясь ускорить усечение таблицы в затравках.
  • Я попытался перейти с PostgreSQL на SQLite для тестов.
  • Я даже задумался о перезаписи сид-файлов

Перестал гоняться за гусем

В конце концов я вспомнил, что нужно измерить, чтобы увидеть, где на самом деле была проблема. Предполагая, что это не тесты, у нас здесь два этапа, clean и seed. Попробуем определить, в чем проблема.

exports.dbCleanAndSeed = async function () {
  let cleanFinishedMs, seedFinishedMs, startMs;
  const options = { ignoreTables: ["knex_migrations", "knex_migrations_lock"] };
  startMs = Date.now()
  await knexCleaner.clean(database, options);
  cleanFinishedMs = Date.now();
  await database.seed.run();
  seedFinishedMs = Date.now();
  console.log("Clean took: %i; seed took %i", cleanFinishedMs - startMs, seedFinishedMs - cleanFinishedMs);
}

Который сделал свое дело и сказал мне, где я должен искать:

site tests
Clean took: 28; seed took 675
    ✓ can get the sites page (732ms)
Clean took: 28; seed took 743
    ✓ get the 'add a new site page' (776ms)
Clean took: 29; seed took 592
    ✓ add a new site (630ms)
Clean took: 26; seed took 594
    ✓ add a site and see it on the sites page (628ms)
Clean took: 29; seed took 748
    ✓ can't add a new site with no creds (779ms)
Clean took: 27; seed took 652
    ✓ gets 404 for a site that doesn't exist (684ms)
Clean took: 30; seed took 732
    ✓ can't add a new site with no domain (769ms)
Clean took: 26; seed took 609
    ✓ can't add a new site with no active value (640ms)

Хорошо. Так что почистить — точно не проблема!

Однако у меня есть пять исходных файлов; Интересно, проблема в каком-то конкретном файле? У нас есть исходный код для knex, так что давайте найдем бит загрузки начального числа и посмотрим, легко ли его инструментировать.

Похоже, что _waterfallBatch() в knex/lib/seed/Seeder.js — это функция, отвечающая за фактическую загрузку сидов, так что давайте сделаем там отметку времени.

async _waterfallBatch(seeds) {
    const { knex } = this;
    const log = [];
    for (const seedPath of seeds) {
      const importFile = require('../util/import-file'); // late import
      const seed = await importFile(seedPath);
      try {
        const startMs = Date.now()
        await seed.seed(knex);
        const endMs = Date.now()
        console.log(`${seedPath} took ${endMs - startMs} ms`);
[...]

Запустить его…

seeds/01_user_seed.js took 147 ms
seeds/02_site_seed.js took 6 ms
seeds/03_review_seed.js took 3 ms
seeds/04_campaign_seed.js took 5 ms
seeds/05_redirect_seed.js took 461 ms

Ой. Да, это довольно убедительно.

Глядя на файл перенаправления, я вижу вероятного виновника.

05_redirect_seed.js:

const geoIpData = await iplocate(remoteIp);

Гео-IP-поиск для каждого загруженного семени. Это бы сработало.

01_user_seed.js:

return knex('users').insert([
        {email: '[email protected]',
         passwordHash: Bcrypt.hashSync("Sherlock",
         parseInt(process.env.BCRYPT_SALT_ROUNDS))
        }])

И хэш bcrypt для каждого вставленного пользователя. Это объяснило бы тот случай.

Вывод

Для начального числа пользователей я сократил солевые раунды Bcrypt до 1 — это только локальное тестирование, поэтому ему не нужно противостоять атакам.

Для перенаправлений я реализовал таблицу поиска для IP-адресов, используемых в начальном файле. Результаты видны сразу:

seeds/01_user_seed.js took 9 ms
seeds/02_site_seed.js took 5 ms
seeds/03_review_seed.js took 5 ms
seeds/04_campaign_seed.js took 5 ms
seeds/05_redirect_seed.js took 8 ms

И это конец. Надеюсь, это поможет кому-то другому!