Я змарнував три дні, щоб пришвидшити обробку запитів на сервісі. Якби повірив своїм очам — знадобилося б три години

Ця детективна історія почалась два роки тому, коли я прийшов на поточний проєкт. Але закони жанру диктують: розповідь треба почати майже з кінця.

Історія в чотирьох реченнях

Розповідь я намагався зробити легкою, корисною та веселою. Такою, щоб не соромно розповідати в барі в п’ятницю у товаристві розробників та розробниць. У такій ситуації зазвичай усі вже знають, хто є хто, який у кого досвід.

Але оскільки ніхто не читає профіль автора та мітки, а ще редакторка DOU попросила це зробити — знайте, що мене звати Дмитро, я маю приблизно шість років комерційного досвіду з JavaScript&TypeScript та Node.js і багатьма пов’язаними речами, працюю на одному й тому ж проєкті в Ciklum другий рік, і мені подобається.

Enjoy the reading.

🧃 Звичайний робочий день. Декілька тижнів тому

Уже другий місяць я єдиний розробник сервісу, що складається з Node.js-серверу та бази з мільйонами рядків (декілька десятків ГБ). На кожен запит у сервіс той робить в середньому 20 запитів в базу. Потім за певними правилами агрегує результат і відправляє JSON у HTTP-відповіді.

Є одна проблема — швидкодія. Вона не критична (була), тому на неї майже не звертали увагу. З плином часу збиралось усе більше звернень від клієнтів, першопричиною яких виявлялась проблема зі швидкодією цього сервісу.

Виявити це було відносно легко. Споживач HTTP API сервісу ігнорував відповідь, якщо сервіс не зміг відповісти за пʼять секунд, та ухвалював рішення за замовчуванням, яке у 95% випадків правильне. До речі, це одна з причин, чому проблему вважали не критичною.

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

Щоб бути впевненим, що запити в базу швидкі, я зробив графік, що показує як довго виконується найбільш повільний запит з усіх в певний проміжок часу. Графік розділений за типами запитів, щоб бачити краще, що відбувається. Бо один тип запиту виконується за 10 мс, а третій — за 600 мс. І для обох то є нормально.

🕵️‍♂️ Цікава деталь

Перед початком дослідження проблеми колега помітив в логах для декількох повільних запитів, що є проміжок між двома лог-повідомленнями, який займає від 500 мс до 800 мс. Це багато.

Це означає, що, ймовірно, виконується важка синхронна операція. Але локально виконання займало 5-8 мс. Повірити, що є сегмент коду сервісу, що виконується локально 8 мс, а на Prod-середовищі 800 мс, я не міг. Кожна пода цього сервісу в k8s запитує 0.5 CPU. Гіпотезу, що це має значення, я відкинув через те, що вона здавалась мені малоймовірною. Хіба таке може бути, що те, що працює локально за 5-8 мс, в k8s працює 800 мс? Напевно так, але не за нормальних умов.

Тому я дослідив ще з десяток повільних запитів і помітив, що інколи цей повільний проміжок траплявся на операцію пізніше, але зазвичай в один і той самий момент. Це змусило мене думати одночасно про два варіанти. Перший: причиною такої поведінки є garbage collector (GC). Другий: я, певно, помиляюсь, бо не може GC спрацьовувати так точно в конкретний момент обробки запиту.

🖥️ Псевдокод того, як я шукав причину повільної швидкодії

📐 Перевірка гіпотез

Спершу я більше вірив у правдивість гіпотези того, що GC винний, бо інших ідей у мене не було. Я перевірив очима код та не знайшов нічого, що може гальмувати. Коли я дивився код, у мене сформувалась друга гіпотеза. Може бути, що якийсь інший код виконується в цей час. Тому що є можливість виконання коду асинхронно, а на логи я дивлюсь уже відфільтровані.

Тому я відклав гіпотезу з GC, у яку мало вірилось, та знову перевірив логи. Цього разу сильно звузив проміжок часу, щоб точно виокремити інтервал обробки конкретного запиту, та прибрав усі фільтри, крім фільтра за ідентифікатором процесу. Оскільки в мене було всього дві гіпотези, я був здивований побачити, що більш ймовірна не підтвердилась. Перевіривши логи для трьох повільних запитів, я побачив, що їм нічого не заважало. У конкретний проміжок часу конкретний процес нічого іншого не виконував.

Тут я згадав, що для цього сервісу нормальне навантаження кожну секунду — це від нуля до 11 запитів. Постійно є підняті шість под сервісу в k8s. І часто в одну секунду вони нічого не роблять, іншу секунду один запит приходить, наступну секунду — 3, наступну — 0, наступну — 12, наступну — 4. Тобто досить часто одна пода оброблює один запит.

❕ Ремарка

Я навмисно НЕ використовую концепцію кількості запитів за секунду в середньому (словосполучення «в середньому» тут головне), тому що клієнта HTTP-сервісу зовсім не хвилює середнє значення. Головне, щоб кожен запит оброблювався не довше пʼяти секунд. Нехай хоч кожен обробляється за 4,99 секунди.

Чому шість под ⁉️

Хочу зробити відступ. Декілька місяців тому їх було всього три. І налаштоване автоматичне горизонтальне масштабування, яке ніколи не масштабувало поди. Ніколи. Їх завжди було три.

Одного разу я помітив стрибок на графіку, що показує кількість повільних запитів. Того разу я був відповідальний за деплой, тому я знав, що різке збільшення кількості «повільних» запитів в 15-20 разів на декілька хвилин точно збігається з моментом, коли DevOps натиснув кнопку Deploy. Стало очевидно, що проблема в кількості подів під час деплою, бо я знав, що деплой відбувається так:

1. Дві поди з трьох зупиняються та підіймаються дві нові. У цей час на HTTP-запити відповідає тільки одна пода.
2. Коли дві нові готові, третя пода заміняється на нову. Не питайте мене, що буде, якщо DevOps укаже некоректні значення для змінних середовища і дві поди не піднімуться.

Помітивши цей стрибок та зрозумівши причину, я використав тактику тисячі й одного електронного листа, щоб змусити аргументувати необхідність тимчасово збільшити кількість подів сервісу. Коли ми в команді побачили, що кількість «повільних» запитів зменшилась удвічі, вирішили не повертати кількість подів до попередньої кількості.

Також в команді з’явилось спільне розуміння, що наразі саме сервіс працює повільно та є вузьким місцем. Не база, не мережа, а сервіс. Це важливий момент, коли всі в команді мають спільне розуміння.

За тиждень чи два ми вирішили зменшити кількість подів, щоб знизити витрати. Нарешті дали можливість покращити швидкодію сервісу.

Повертаємось до сьогодення.

🗿 Трейсинг виконання

У мене є дві гіпотези, чому сервіс повільно обробляє запити. Одна — про асинхронний код, яка не підтвердилась. Друга — про GC, у яку я майже не вірив. У мене є логи, графіки та код сервісу. Також у мене немає доступу до Prod-середовища, щоб додати чи прибрати логи швидко.

Намагаючись зрозуміти, чому в логах повільне місце то тут, то на операцію пізніше, я запускав у режимі налагодження (debug mode) сервіс. Та знову і знову відправляв запити. Робив трейсинг очима. Кожен рядок коду. Результат мене трішки розчарував, але і змусив сміятись. Повідомлення в логах некоректно відсортовані. По-перше, не було місця, де б вивід логів був за умовою (if statement).

По-друге, я помітив, що сортування логів некоректне в тому разі, коли повідомлення були сформовані в одну і ту ж мілісекунду. Це дозволило мені відкинути гіпотезу з GC. Також я зрозумів, який саме метод працює з 500 мс до 800мс на Prod-середовищі, тому що я на пам’ять знав, якому логу відповідає який метод. Додатково я перевірив, скільки часу займає виклик цього методу для інших HTTP-запитів, які відпрацювали швидше за пʼять секунд. Підтвердилось те, що повільний метод — завжди повільний.

Але як так? Чому? Чому локально це 8 мс, на QA-середовищі це 200 мс, а на Prod-середовищі 800мс? Кожна пода цього сервісу в k8s запитує 0.5 CPU. Може занадто слабкі поди? Як це перевірити? Скільки вони мають вимагати CPU? Потрібні нормальні метрики, яких на проєкті не було. На додачу до цих запитань стояло ще одне. Чому є різниця у швидкодії одного і того ж методу між QA- та Prod-середовищами? Чому різниця така велика?

🪔 Медитація над логами

У пошуках наступних гіпотез, я медитував над логами. Раптом мене ошелешило: чому я ці логи взагалі бачу?! Їх тут не має бути. Я їх прибрав дві версії тому. Навіть якщо так, то чому в них інший log level?

Логи, яких не має бути, писав пакет-залежність. За нього відповідала інша команда, але я знав його код. Якщо log level інакший, досить ймовірно, некоректна версія пакета використовується на Prod-середовищі. Якщо версія неправильна, то ті зміни, що я робив до пакету-залежності місяць тому, щоб покращити швидкодію, також не працюють на Prod-середовищі!

Прокляття старого Azure Classic Pipelines

Пакет, що генерує логи_яких_не_мусить_бути, називається умовно @thecompany/the_package. Я знав, що він робить, та робив деякі зміни місяць тому, щоб покращити швидкодію. Вперше пакет потрапив мені на очі півтора роки тому, коли в CI я побачив npm install @thecompany/[email protected] а після нього npm install. Що було досить дивно.

Навіщо встановлювати конкретну версію пакета? На питання «Навіщо в CI оцей крок?» мені колега відповів, що без першого кроку не працює наступний. І взагалі нічого не працює. Це було ще дивніше. Але CI змінювати тоді мені не можна було, і всі були дуже зайняті терміновими задачами, тому залишилось як є.

Однаково незрозуміло було, чому версія на проді некоректна. Тому що півроку тому я змінив RUN npm install на RUN npm ci в Dockerfile сервісу, поки ніхто не бачив. Здавалось, яка різниця, що там в пайплайні, якщо Dockerfile правильний?

З думкою, що кращої гіпотези в мене немає, і, можливо, Cloud provider щось наоптимізував, я вніс зміни до CI. Так, у мене вже були дозволи змінювати CI, завдяки тому, що я вибив їх з DevOps шантажем і підкупом зміг аргументувати, чому розробники мають мати можливість змінювати CI.

Гіпотеза підтвердилась. Якщо прибрати з СІ дивний крок npm install @thecompany/[email protected], в docker-образі теж буде коректна версія.

Прокляття будь-якого npm

До речі... Уявімо, що у вас проєкт у package.json, у якому одна зі всіх залежностей є lodash@^4.17.21. Чи знаєте ви, який результат виконання команди rm -rf ./node_modules && npm install [email protected]? Я був здивований.

П’ять страшних мегабайт

Отже після змін в CI логи, яких не має бути, зникли. Також зникли «повільні» запити. І стало зрозуміло, чому є різниця між Prod- та QA-середовищами.

Повільні запити зникли, бо зміни до пакета @thecompany/the_package, що я робив місяць тому, попали в docker-образ. Нарешті. Той повільний метод сервісу працював довго через cloneDeep великого об’єкта. Оскільки сервіс не робив мутацій об’єкта, місяць тому я додав можливість відімкнути cloneDeep.

На QA-середовищі повільний метод сервісу відпрацьовував швидше, тому що об’єкт, який копіювався на Prod-середовищі, був разів зо два більший. Я теє зрозумів, коли мені згадалось, що рік тому мій колега вирішив логувати той об’єкт під час старту сервісу. Об’єкт було приблизно 5 МБ. Логер чомусь вмирав назавжди. Коли зміни деплоїли в Prod-середовище, сервіс не писав логи, і його відкотили.

Про всяк випадок у CI я замінив npm install на npm clean-install.

На додачу я зробив мемоізацію для повільного методу, щоб він не робив одну й ту ж роботу на кожен запит від конкретного клієнта. Увесь набір налагоджень та трюк з мемоізацією дозволив прискорити повільний метод в 800 разів. Бо майже 0 в 800 разів швидше ніж 800 мс.

Історія в чотирьох реченнях

Сервіс повільно обробляв запити, тому що пакет-залежність робив deepClone об’єкту розміром 5 МБ. Після змін у пакет нічого не змінилося, тому що за build docker образу Classic Azure pipeline виконувала «дивний» крок і підкладала некоректну версію пакета. Я ще додав мемоізацію для методу, тому що можна не блокувати Event loop на 20 мс знову й знову на кожен HTTP-запит. Після всіх змін замість 800 мс «повільний» метод виконується за майже 0 мс.

Мораль історії

Добре роби, добре буде.

Цієї історії не було б, якби півтора роки тому з Azure Classic CI Pipeline прибрали дивний крок. Цієї історії не було б, якби був налаштований моніторинг Event loop delay. Цієї історії не було б, якби пакет-залежність використовував TypeScript та повертав DeepReadonly об’єкт, замість того, щоб робити cloneDeep гігантського об’єкту. Цієї історії не було б, якби я повірив своїм очам 👀.

Дякую за увагу.

Підписуйтеся на Telegram-канал «DOU #tech», щоб не пропустити нові технічні статті