Історія одного передноворічного релізу

[Про автора: Дмитро Меньшиков — CTO в Aurora Technologies. Програмує вже 15 років, в highload 9 років, 6 років в ролі менеджера. Основною своєю роботою вважає вирощування інженерів і розвиток інженерних підходів як в компаніях, які будував, так і на ринку в цілому. Активний учасник International Software Architect Club, Kyiv CTO Meetup, PHP Friends Club. Спікер на конференціях. Вірить, що хороші продукти в IT створюють лише менеджери з технарів. Кредо: мови і технології — всього лише інструмент досягнення мети, а рішення проблем є завжди точкою росту]

Ця історія сталася в кінці грудня 2017 року, в його останні дні. Поки люди билися за їжу, відвойовуючи останні лотки яєць на вітринах супермаркетів, відходили від похмілля після останньої п'ятниці, що минає, я ніяк не міг знайти святковий настрій. Всьому виною був проблемний передноворічний реліз. Над пошуком причини я бився вже кілька днів, але не бачив зачіпок. 29 числа я змирився, що пошук буде тривалим та складним, і продовжу я його вже в 2018 році, але з самого ранку 30 грудня в голову почали лізти думки...

Історія покликана послужити гайдлайном при вирішенні завдань. Я постарався максимально детально описати хід своїх думок і вектор пошуку рішення. Але почну історію з опису самого релізу.

Реліз і пошуки проблеми

Протягом майже двох років ми жили з видеостриминговой підсистемою, яку нам здали в експлуатацію аутсорсери. На етапі приймання не було достатньої експертизи, що і послужило мотивацією до замовлення аутсорс-послуг, а в ході експлуатації були виявлені критичні недоробки. Взагалі рішення виявилося наколеночным і жодного разу не enterprise. Аутсорсери якось туго вирішували проблеми, навіть з наявністю платної підтримки. Складалося враження, що там тільки один адекватна людина в команді, і той вічно засмиканий. Я і команда намагалися вирішити проблеми в рамках вже існуючого рішення, але вартість зашкалювала. Ті, хто стикався з live streaming, напевно, уявляють, який гемор перепиливать сишный транскодер на базі libx264, коли порушена логіка роботи з time frames, CBR просто не забезпечити, щоб прикрутити нарізку HLS, потрібно сісти на шпагат на два стільці, проміж яких піки точені...

Так і виникло вольове рішення викинути ось це ось все — і написати правильно і красиво. У створенні правильного і красивого команда провела сім місяців... Я взяв на себе зобов'язання викотити ці глобальні зміни в 2017 році, в грудні. Обіцянки потрібно виконувати, а коли начебто все перевірили і все було окей, то зарелизились. За 13 днів до НГ. Поки були зайняті міграціями і перевіркою коректності організаційної частини, перший партнер-користувач системи зауважив, що кількість помилок HTML5 плеєра зросла.

До того моменту ми побачили, що десь облажались. Засукавши рукава, взялися шукати проблеми. Досить оперативно були знайдені десятки різноманітних недоліків: таймаут, які виникали з-за забитого ThreadPool в Node.js помилки логіки, помилки адмінів з конфігуруванням, з системами оркестрации і т. д.

Все це вдавалося вирішити за лічені години, але була одна проблема, яка ніяк не піддавалися поясненню. Логи не містили нічого аномального, перевірки інфраструктури і конфіги серверів з маршрутизаторами виявилися безрезультатними. На транскодерах, які приймають вхідні RTMP-потоки від ingest-серверів (а ingest від стримерів), займаються перекодуванням звуку і відео в декількох якостях, відбувалися фризи!

На оновленому транскодере був реалізований механізм детекта фриза: транскодер-сервіс завершував роботу транскодер-процесу при відсутності відео/аудіо кадрів упродовж певного часу. Транскодер-сервіс ще повідомляв командний центр про цю проблему, а командний центр намагався перезавантажити частина таких завдань. Транскодери тягнуть RTMP-потоки з ingest-серверів, а в ролі ingest-серверів виступають сервери з Wowza. Крім транскодеров, з ingest тягнуть потоки: сервіс контролю якості, сервіс по нарізці preview з відеопотоку, сервіс запису... Майже на всіх з них є механізм визначення фризів. Ось і випливли ці множинні фризи на відеопотоків...

Крім логів є ще метрики! Ключові метрики системи відправляються в Zabbix, а швидкі або ж не самі основні — в Graphite. Перечитавши логи і переглянувши метрики, прийшли до висновку, що фризи не поодинокі і виникають групами. Графік нижче показує кількість потоків після транскодування, доступних до перегляду. До релізу і після релізу.

У більшому масштабі це виглядало так:

Поки творилася плутанина, на одному з серверів був знятий лог підключень і відключень стримерів, а також дані з журналу детекту фриза. Часовий діапазон для аналізу було взято з Zabbix. Ще раз зазначу, що це один і той же ingest-сервер.

0ec147369caddd33ebdf95be72532cd1:
2017-12-28 01:29:42 published vss-w-p-6
2017-12-28 01:59:06 freeze on transcoder vss-crabscoder-9
2017-12-28 02:00:06 unpublished vss-w-p-6

52934993316c56a20731d755917e6146:
2017-12-28 01:30:55 published vss-w-p-6
2017-12-28 01:59:08 freeze on transcoder vss-crabscoder-6
2017-12-28 02:06:57 unpublished vss-w-p-6

27581ab5a170e0467261ad6fc070ee33:
2017-12-28 01:46:18 published vss-w-p-6
2017-12-28 01:58:55 freeze on transcoder vss-crabscoder-3
2017-12-28 02:05:53 unpublished vss-w-p-6

Але при цьому були й потоки, які не фризились.

49ee6016e84e6ae8d2000efac50ea7d6:
2017-12-28 00:46:19 published vss-w-p-6
2017-12-28 04:18:19 unpublished vss-w-p-6

3b125f18c52d9eb914144088ed8c142f:
2017-12-28 01:10:34 published vss-w-p-6
2017-12-28 06:39:44 unpublished vss-w-p-5

4cc7d1fb938038b774264e23450846b2:
2017-12-27 23:50:46 published vss-w-p-6
2017-12-28 02:45:24 unpublished vss-w-p-6

Факт 1. Не з усіма потоками на одному і тому ж сервері були проблеми.

Разом з тим в логах Wowza ще проскакували запису про таймаутах.

WARN server comment 2017-12-20 15:07:11 - - - - - 188991.31 - - - - - - - - LiveMediaStreamReceiver.doWatchdog: streamTimeout[origin/_definst_/d7350b04480f90affd092816157a8dba]: Resetting connection: wowz://10.2.1.174:1935/origin/_definst_/d7350b04480f90affd092816157a8dba
WARN server comment 2017-12-20 15:07:11 - - - - - 188991.311 - - - - - - - - LiveMediaStreamReceiver.doWatchdog: streamTimeout[origin/_definst_/7c4728f4a266216c1a9c2a9ebad191ed]: Resetting connection: wowz://10.2.1.174:1935/origin/_definst_/7c4728f4a266216c1a9c2a9ebad191ed
WARN server comment 2017-12-20 15:07:11 - - - - - 188991.312 - - - - - - - - LiveMediaStreamReceiver.doWatchdog: streamTimeout[origin/_definst_/a8643913cef9e21a403416018bdf8e88]: Resetting connection: wowz://10.2.1.174:1935/origin/_definst_/a8643913cef9e21a403416018bdf8e88

Факт 2. На Wowza спостерігається обрив потоків по таймауту. Незрозуміло, на прийомі потоку або роздачі.

В саппорт почали надходити скарги від клієнтів. Всі стверджували, що їх викидає з інфраструктури. У кожного своє уявлення про те, що таке «викидає», але саппорт висунув факт...

Факт 3. Стримерів періодично примусово викидає з інфраструктури.

Інша частина команди перевірила логи на ingest, origin і транскодере, і прийшла до висновку...

Факт 4. Потік обривається на ingest, потім інфраструктура це помічає і шле команду зупинити обробку на origin, далі це помічає транскодер, і ми спостерігаємо SIGPIPE.

Зазначу, що SIGPIPE — це сигнал, що відправляється процесу в тому випадку, якщо з'єднання з сокетом, в який відбувається запис, процесом обривається. Тобто якщо писали в сокет, а він закрився/мережа обірвалася.

Ще подивилися графік подій дисконектов з ingest, і стало зрозуміло, що вони були і раніше, але їх було менше. Штатні це дисконекты чи ні, по логам зрозуміти було не можна.

Факт 5. Кількість дисконектов виросло на тій же кількості трафіку.

Останній факт виплив із спостереження за життям потоків. З'ясувалося, що за сесії стрімінг кілька разів міг настати фриз або зупинка процесу транскодування за SIGPIPE сигналу, процес транскодування перезапускається, і трансляція тривала.

Звівши всі відомі на той час факти, ми висунули припущення, що проблема з ingest-шаром. На це вказували і фризи, які були індикатором того, що не надходять дані потоку, і обривалися не відразу всі потоки, а тільки частину.

Ще раз обговорили план дій і зафіксували подальші кроки:

Перевірити запити з боку бізнес-логіки, щоб виключити те, що внаслідок бага ми вбиваємо.
З'ясувати по логам, що або хто ініціював дисконнекты з інжеста. Пункт проблематичний, бо потоки надходять від зоопарку софта, flash-додатків, hardware encoders, OBS, XSplit і т. п. Кожне з додатків може вести себе інакше.
Треба зібрати повну карту дій стримерів від підключення до відключення: хто підключався на перегляд, хто відключався, як змінювався статус потоку. Все-все-все.
Перевірити лог кожного з Wowza-сервісів по окремості на предмет наявності тимчасових інтервалів без логів (заблокувалося ЗА, наприклад).
Хто з стримерів залишався після обривів і чи є якась кореляція?
Перевірити з дебагерами вовзу і переглянути повний діфф між минулою версією і поточної. При необхідності перебудувати Wowza з покриттям логами всіх нових ділянок, а також перевірити блокування між процесами.
Перевірити IDLE і показники як харднод серверів, так і віртуальних машин. Раніше моніторинг не помічав нічого, але мало що...
Навіть перевірити фронтенд клієнтів, мало що...
Провести спостереження за ingest, познімати трафік, познімати логи.

Чекліст перших припущень:

Винен дата-центр, і проблема у них, десь втрати на каналі.
Винні адміни, маршрутизатор або сервера.
Винна Wowza.

Інженери не визнають наявність проблем в коді! Звичайно ж, винні адміни, мережа, сервера і навіть небо, навіть Аллах. Адмінів почали допитувати, а поки йшов допит, вони встигли уточнити у дата-центру, немає проблем. Дата-центр не підтвердив наявність проблем, наші моніторинг-тули теж не знаходили аномалій. Не було жодного розриву. Розробники відразу пригадали адмінам всі колишні косяки. Була якось проблеми з прошивкою мережевої карти, і відповіді nginx з ramfs займали непристойно багато. У той раз адміни не визнавали наявність проблем до останнього, теж звинувачували розробників. Класика: адміни звинувачують девелоперів, а девелопери звинувачують адмінів. QA при цьому звинувачують всіх, крім себе.

Отже, роботи розділені між розробниками і адмінами, і всі приступили до своєї частини.

Через деякий час в логах consul були помічені проблеми з TCP-з'єднаннями, які відбулися в той же час, що і обриви.

Dec 28 15:08:34 vss-we-3 consul[22751]: memberlist: Failed TCP fallback ping: read tcp 10.2.0.229:39386->192.168.8.3:8301: i/o timeout

consul використовується в якості service discovery всіх сервісів системи. Тим не менше ми сприйняли це як знак. Наша впевненість в інфраструктурній проблеми зростала.

При аналізі логів були знайдені слабкі місця, коли в логах не вистачало інформації. Заводяться завдання на розширення зібраних даних в логи, а це все затягує налагодження. Так, наприклад, новий транскодер не в повній мірі повідомляв, хто генерував завдання і відправляв керуючі команди. А це дуже критично для відновлення всієї картини...

Таких дрібних косяків безліч, і вони гальмують з'ясування.

Крім іншого, я собі взяв пункт 9. Доля така у CTO... вічно займатися неформалізованою хардкором в умовах невизначеності. В рамках цього пункту вирішено було почати з дослідження потоків з ingest, а саме — видеочасти.

Непогано було б отримати повний висновок по кожному кадру відео і аудіо: розмір, дату, знайти деякі кореляції. Для аналізу відео, як статичного, так і live, є чудовий інструмент ffprobe . Він дозволяє в риалтайме отримувати інформацію про потоці, інформацію про фрейми, тривалість кадру, час за шкалою encoder на стороні, що відправляє потік. 30 хвилин, і я написав скрипт на Node.js для контролю за ingest-серверами і логування виведення ffprobe по всіх потоків на всіх серверах.

Для дотримання достовірності додам і саму команду:

ffprobe -i rtmp://host:port/path -show_frames

Але висновок покаже послідовність кадрів, а ще цікаво дивитися за часом, коли ці кадри були отримані процесом ffprobe. Так можна визначити відставання і залипання. Для цих цілей я прикрутив запис в лог-файл ffprobe з інтервалом раз в 5 секунд тимчасової мітки.

Код написаний і запущений, а я засів дивитися логи кибаны і графік заббикса.

Через 40 хвилин були словлены фризи. Потираючи руки, лізу аналізувати висновок ffprobe.

[FRAME]
media_type=video
stream_index=0
key_frame=1
pkt_pts=117285
pkt_pts_time=117.285000
pkt_dts=117285
pkt_dts_time=117.285000
best_effort_timestamp=117285
best_effort_timestamp_time=117.285000
pkt_duration=33
pkt_duration_time=0.033000
pkt_pos=3406194
pkt_size=32358
width=854
height=480
pix_fmt=yuv420p
sample_aspect_ratio=1:1
pict_type=I
coded_picture_number=456
display_picture_number=0
interlaced_frame=0
top_field_first=0
repeat_pict=0
[/FRAME]

[FRAME]
media_type=video
stream_index=0
key_frame=1
pkt_pts=127421
pkt_pts_time=127.421000
pkt_dts=127421
pkt_dts_time=127.421000
best_effort_timestamp=127421
best_effort_timestamp_time=127.421000
pkt_duration=33
pkt_duration_time=0.033000
pkt_pos=3440357
pkt_size=35030
width=854
height=480
pix_fmt=yuv420p
sample_aspect_ratio=1:1
pict_type=I
coded_picture_number=457
display_picture_number=0
interlaced_frame=0
top_field_first=0
repeat_pict=0
[/FRAME]

На наступний день почав аналізувати зібрані логи. Для цього написав простенький скрипт , який витягав pkt_dts_time з лода і агрегировал з 5-секундним інтервалам кількість фреймів. Ще він вважав кількість фреймів у позначці реального часу, які я писав у файл. Після побудови gnuplot скриптом графіка стали видні дропи візуально.

PTS — presentation time stamp, DTS — decoding time stamp. У фреймі pkt_pts_time і pkt_dts_time будуть відрізнятися тільки при наявності predictive (P) кадрів. Так що для аналізу можна взяти DTS, і різниця між pkt_dts_time у двох послідовних кадрів буде відображати час між энкодингом двох фреймів.Подробиці тут .

Судячи з графіку, з стримами відбувалося чорт знає що, FPS не витримувався, вічно скакав, DTS (decoding time stamp) змінювався паблішинг клієнтом і перескакував на кілька десятків секунд вперед. За realtime-графіку видно, що і Wowza віддавала кадри для ffprobe з фризами. Сам графік кількості кадрів realtime не показав нічого нового, адже і так ловили ці проблеми на транскодерах. Графік кількості кадрів DTS timebase був досить цікавим. Так вести себе енкодер на стороні стримера може в тому випадку, якщо Wowza не читає вхідний потік з сокета. У цьому випадку клієнт просто пропускає фрейми і чекає, поки буфер на стороні Wowza очиститься.

Підозра впала на Wowza.

Пора розповісти про Wowza. Це пропрієтарний софт з закритим кодом і помісячною оплатою, крутими можливостями за свої гроші. Поки ти не починаєш користуватися продуктом...

Йде час, ти вляпываешься в проблеми і дивна поведінка, пишеш саппорт. Бравий саппорт відповідає через пару днів і запитує логи. Окей, высылаешь їм логи. Нічого, що логи вже були приаттачены до тікети, конфігурація була описана — може, що пропустили. Хлопці туплять ще пару днів і запитують повнілоги. Ну ладно, хочете читати кілька гігабайтів логів з моменту запуску? Будь ласка. Проходить ще кілька днів, саппорт запитує ще логи. WTF? Які ще логи? Саппорт непохитний: за вашим логів ми не можемо зрозуміти проблему, дайте більше логів. Звідки ж їх взяти, якщо і так debug-режим включений? Пацанів це не хвилює! «Дайте більше логів!» — напевно, так виглядає їх корпоративний гасло.

Один раз, на IBC в Амстердамі, ми познайомилися з їх топ-керівництвом і хотіли помітингувати на їх стенді, і таки вирішити з ними проблеми. Від нашої ідеї їх Vice President of Engineering зажурився, але запропонував бухнути з ними, а проблеми пообіцяв вирішити після IBC. Чи варто уточнювати, що в результаті вони знову випали на мороз?

Тим не менш треба вирішувати проблему. Щоб виключити Wowza, можна було б підняти nginx з nginx-rtmp-module , а перед Wowza ingest поставити HAProxy/teeproxy/etc і дублювати трафік. Можна було б дублювати трафік правил iptables. Тоді можна було б дублювати один і той же потік на два різних додатки, які беруть RTMP, і дивитися різницю на них. Ідея провалилася, так як у rtmp присутній handshake, і другий nginx з nginx-rtmp-module просто відкине з'єднання із-за кривих відповідей на handshake.

Поки думали над можливістю таки розпаралелити потоки, прибрали перевірку фризів з транскодеров. Проблему це не вирішило. Транскодер продовжував чекати, але і на origin не відправляв фрейми. Origin чекав кілька десятків секунд, і потім сам закривав з'єднання з транскодером. Ці закриття теж детектились транскодером, і він завершувався з сигналом SIGPIPE.

Тим часом почали обговорювати блокування на стороні Wowza...

На нашій збірці Wowza присутні самописні модулі для авторизації, контролю прав, повідомлень про підключення, відключення, allow lists і т. п. Wowza запускає безліч тредів і слухає входять RTMP-з'єднання. На серверах достатньо оперативної пам'яті і ядер, а навантаження менше 10%. Так що перевантаження відразу виключили.

Але залишилися питання з модулями. В самописних модулях Wowza на Java в shared memory зберігаються хэшмапы з інформацією про стримах, про сервери для нотифікацій. Отримання IP-адрес, на які потрібно надсилати повідомлення, відбувається по інтервалу (раз в 5 секунд), і результат записується в shared memory. Для того щоб безпечно читати і писати з shared memory, потрібно ставити блокування. В Java коді це вирішується або явно, або з використанням synchronized блоків. У нас використовувався другий варіант, але суті це не змінює.

Тому виникло припущення, що Wowza десь блокується, то з-за нашого кривого коду, то за її коду. Перевірити це можна, лише приєднавшись до процесу strace'ом.

Strace — це досить потужний інструмент для низькорівневої відладки: він пише системні виклики, пише аргументи, передані функцій, повернені значення після виконання функцій, час виконання функції, а також pid сабпроцесса/треда, в якому відбувався виклик.

Адміни відразу виконали strace -c -f -p123. Аргумент -c вказує вважати кількість часу, викликів і помилок в кожному з системних викликів. Висновок на працюючому ingest був таким:

% time seconds usecs/call calls errors syscall
 ------ ----------- ----------- --------- --------- ----------------
 98.27 164058.185756 129258 1269232 328380 futex
 0.96 1607.779169 10882 147742 epoll_wait
 0.26 437.918455 283 1546081 198 write
 0.20 339.308117 86119 3940 poll
 0.15 245.116958 247 991033 clock_gettime
 0.09 148.213531 3293634 45 41 restart_syscall
 0.05 89.647620 280 319628 144406 read
 0.00 4.673533 268 17416 lseek
 0.00 1.546572 239 6478 getrusage
 0.00 1.316333 243 5408 346 epoll_ctl

Вище вже згадувалося, що система була не особливо навантажена, тому відразу ж припустили, що дивне діялося з Wowza, і безліч потоків очікували зняття блокувань. TL команди відразу почав займатися кодом модулів Wowza в такому порядку:

статичний аналіз diff-коду до релізу і після;
додати логування входів/виходів в synchronized блоки в голих модулях, проведений час і кількість претендентів заблокувати блок.

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

Наступна гіпотеза — блокуються наші самописні модулі Wowza.

Поки TL займався Wowza модулями, я продовжив долбаться з strace і вирішив зібрати лог всіх викликів і намагатися відновити історію, хоч і з bird eye view.

Щоб зібрати все, що мені було потрібно, потрібно запустити strace -t -T -f -p123, де

123 — pid Wowza процесу;
-t додає в початок рядка дату і час, що нам вкрай важливо для зіставлення проблем;
-T додає час, витрачений на виклик, про це окремо розповім нижче;
-f додає pid child процесу висновок, для мультіпоточних додатків без цього прапора нікуди.

За 22 хвилини з одного ingest зібрали 5 Гб логів проміжок з 2017-12-28 13:58 за 2017-12-28 14:20.

Виглядають вони приблизно наступним чином:

26484 13:58:09 futex(0x7f4d7006ff38, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
26477 13:58:09 futex(0x7f4d70064904, FUTEX_WAIT_PRIVATE, 1432479, NULL <unfinished ...>
25693 13:58:09 futex(0x7f4d60445e18, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
25225 13:58:09 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) <0.000164>
24755 13:58:09 <... futex resumed> ) = 0 <0.000165>
30942 13:58:09 read(125, <unfinished ...>
20197 13:58:09 write(178, "\307", 1 <unfinished ...>
13033 13:58:09 epoll_ctl(132, EPOLL_CTL_MOD, 159, {EPOLLIN, {u32=159, u64=159}} <unfinished ...>
9900 13:58:09 write(145, "\307", 1 <unfinished ...>
14275 13:58:09 write(176, "\307", 1 <unfinished ...>
21229 13:58:09 <... write resumed> ) = 104 <0.000134>
26484 13:58:09 <... futex resumed> ) = 0 <0.000134>
25693 13:58:09 <... futex resumed> ) = 0 <0.000125>
25225 13:58:09 futex(0x7f4db0006e28, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
30942 13:58:09 <... read resumed> "\304\262-\244\324\327H\200\266\27#\27)\213\274
\341\247,Z\373\227\334#-\242l\321\254b@\220"..., 65000) = 105 <0.000109>
20197 13:58:09 <... write resumed> ) = 1 <0.000115>
13033 13:58:09 <... epoll_ctl resumed> ) = 0 <0.000118>
21229 13:58:09 write(149, "G\0\0\37\0\4^\t", 8 <unfinished ...>
26484 13:58:09 futex(0x7f4d7007c834, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f4d7007c830, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
25225 13:58:09 <... futex resumed> ) = 0 <0.000095>
30942 13:58:09 read(125, <unfinished ...>
20197 13:58:09 write(178, "\343g\265c\177\232\365~\376\307w\337e\314(\227\33\251\357\363\327\372Z\374}\6\210~\344\34\246\263"..., 512 < unfinished ...>
13033 13:58:09 epoll_wait(132, <unfinished ...>
9900 13:58:09 <... write resumed> ) = 1 <0.000277>

Розберемо цей шматок порядково.

25693 13:58:09 futex(0x7f4d60445e18, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>

pid child процесу 25693, ймовірно, це один з тредів Wowza. В 13:58:09 був здійснений системний виклик futex .

Futex — це механізм (і він же системний виклик) для можливості реалізації синхронізації між потоками в user-space, з використанням shared memory ще й між різними процесами. Правда, в цьому випадку доведеться-таки виконати операцію в kernel-space. Можливість синхронізації user-space працює на порядок або навіть два швидше, ніж при використанні логіки в kernel-space.

Справа в тому, що при синхронізації user-space не потрібно зупиняти виконання програми і не потрібно перемикатися на виконання коду ядра, що економить багато ресурсу CPU. Системний виклик futex атомарно перевіряє комірку пам'яті на відповідність певному значенню і блокує виконання потоку, в якому був запущений (виклик). Це важлива частина роботи з багато-додатками, що використовують доступ до ресурсів, що розділяються, з різних потоків. Без блокувань кілька потоків можуть спробувати отримати доступ до одного і того ж ресурсу, і все може виконуватися не так, як задумав програміст. Знаєте жарт: «I had a problem, so I decided to use threads. tNwoowp rIo bhlaevmes»?

Еволюція механізмів блокувань і їх мінуси/плюси — велика тема. Тим, хто зацікавився, можна почати з переліку публікацій в цій відповіді на Quora . В даній публікації є приклади коду для розуміння логіки роботи futex. Нам же достатньо фактів, що futex без таймауту може необмежено довго блокувати інші потоки, викликаючи деградацію. А ще в разі краху треда, який ставив блокування, можуть не знятися локі в інших потоках (залежить від реалізації, а вона у нас black box).

Інтерфейс системного виклику такий:

int futex(int *uaddr, int m, int val, const struct timespec *timeout, int *uaddr2, int val3);

Перший аргумент uaddr (значення uaddr === 0x7f4d60445e18) може стати в нагоді, якщо декілька потоків з різними pid спробують поставити блокування з тією ж адресою. В цьому випадку по uaddr можна знайти тред, який успішно поставив блокування, і з'ясувати, чому він довго її не знімав. uaddr є покажчиком на область пам'яті.

Виклик futex був здійснений з аргументом FUTEX_WAIT_PRIVATE, і це вказує системного виклику, що потрібно порівняти значення за адресою uaddr з третім аргументом (в нашому випадку це 1) і заблокуватися (можливо, з таймаутом, але виклик був без таймауту).

Перший рядок файлу — це pid child процесу. Як видно з лода, результат цього виклику знаходиться кількома рядками нижче, з тим же pid:

25693 13:58:09 <... futex resumed> ) = 0 <0.000125>

Результат виконання 0, і це означає, що блокування знято (для операції FUTEX_WAIT_PRIVATE).

Операції читання і запису (read і write ) працюють з файловими дескрипторами, і без контексту складно зрозуміти, з чим пов'язаний дескриптор. Але до читання або запису повинен відкритися або файл, або сокет, так що варто шукати інші системні виклики по цьому файловому дескриптору та ідентифікувати, що ж це за файл. Добре, що read повертає кількість прочитаних байтів, що корисно для аналізу. А за ловга виклику write можна побачити бажане кількість байтів для відправки і фактичне значення. Для ворожіння на кавовій гущі підійде!

Отже, є безліч рядків читання і запису, відомі їх дескриптори. Завдання полягає в тому, що потрібно знайти сокет нашого залип з'єднання, як і тред, у якому виконувалося читання і запис.

На допомогу мені прийшла кмітливість. Протокол rtmp реалізовує RPC , можна почати шукати по командам. Нас цікавить паблішинг стріму на Wowza, а згідно rtmp для початку паблишинга потрібно виклик команди createStream.

The client sends this command to the server to create a logical channel for message communication. The publishing of audio, video, and metadata is carried out over channel stream created using the createStream command. The command structure from the client to the server is as follows:

+--------------+----------+----------------------------------------+
 | Field Name | Type | Description |
+--------------+----------+----------------------------------------+
 | Command Name | String | Name of the command. Set to |
 | | | "createStream". |
+--------------+----------+----------------------------------------+
 | Transaction | Number | Transaction ID of the command. |
 | ID | | |
+--------------+----------+----------------------------------------+
 | Command | Object | If there exists any command info this |
 | Object | | is set, else this is set to null type. |
+--------------+----------+----------------------------------------+

Клієнт plain text'му буде слати createStream, і він буде перебувати на початку пакета. Якщо мені пощастить, то createStream буде знаходитися в перших десятках байтів, і цей рядок потрапить до strace. В іншому випадку довелося б шукати за іншими заголовками, і було б складніше.

$ grep -n "createStream" strace_wowza_p5_13-58_14-20
7557250:20197 14:00:47 <... read resumed> "C\0\1\33\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000159>
17282898:20197 14:04:16 <... read resumed> "C\0\3\36\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000099>
22014818:21229 14:06:01 <... read resumed> "C\0\2]\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000114>
30542512:20197 14:09:07 <... read resumed> "C\0\3\36\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000100>
31817555:14275 14:09:36 <... read resumed> "\3\0\0\334\0\0\32\21\0\0\0\0\0\2\0\fcreateStream\0@\0\0"..., 65000) = 38 <0.000143>
32871539:9900 14:09:59 <... read resumed> "\3\0\2J\0\0\32\21\0\0\0\0\0\2\0\fcreateStream\0@\0\0"..., 65000) = 38 <0.000078>
46524834:21229 14:14:57 <... read resumed> "\3\0\2%\0\0\32\21\0\0\0\0\0\2\0\fcreateStream\0@\0\0"..., 65000) = 38 <0.000141>
46607865:30942 14:14:59 <... read resumed> "C\0\2f\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000132>
48653251:21229 14:15:42 <... read resumed> "\3\0\1
\0\0\32\21\0\0\0\0\0\2\0\fcreateStream\0@\0\0"..., 65000) = 38 <0.000186>

Бінго! Є підключення. Цікаво, що в тред з pid === 20197 аж 3 стріму знайшлося. Тепер на допомогу прийдуть логи кибаны. За ним варто пошукати початок операції стрімінг і зіставити, були в період спостереження за Wowza фризи.

Стріми знайшлися:

a144380f9dd83643c756884ca1d55150:
2017-12-28 14:04:17 published vss-w-p-5
2017-12-28 14:17:28 SIGPIPE origin from
2017-12-28 14:23:20 unpublished vss-w-p-5

5773e9ab70202cbb98868e477aff0d1a:
2017-12-28 14:06:01 published vss-w-p-5
2017-12-28 14:07:48 freeze on transcoder vss-crabscoder-8
2017-12-28 14:09:56 unpublished vss-w-p-5

e8024496a02282138285b6f2460e5bdc:
2017-12-28 14:11:25 published vss-w-p-5
2017-12-28 14:17:40 SIGPIPE origin from
2017-12-28 14:41:19 unpublished vss-w-p-5

4852e7d0125ab780057742a78edae88d:
2017-12-28 14:14:58 published vss-w-p-5
2017-12-28 14:17:21 SIGPIPE origin from
2017-12-28 14:24:52 unpublished vss-w-p-5

4a8a32f1ea637df5c1900e5c0c2fb407:
2017-12-28 14:15:00 published vss-w-p-5
2017-12-28 14:17:21 SIGPIPE origin from
2017-12-28 14:23:34 unpublished vss-w-p-5

Попрацюємо з тредом з pid === 20197, в якому відбувалося читання відразу двох проблемних стримов. Відсікаємо зайві дані і грепаем тільки з цього pid.

$ grep '^20197' strace_wowza_p5_13-58_14-20 > strace_p5_20197

Результуючий файл вийшов немаленьким — 368 Мб. Тепер пошукаємо дескриптор.

$ grep 'createStream' -C 2 strace_p5_20197
--
20197 14:04:16 <... epoll_wait resumed> \{\{EPOLLIN, {u32=99, u64=13110842216018870371}\}\}, 8192, 500) = 1 <0.011427>
20197 14:04:16 read(99, <unfinished ...>
20197 14:04:16 <... read resumed> "C\0\3\36\0\0\32\21\0\2\0\fcreateStream\0@\0\0\0\0\0\0"..., 65000) = 34 <0.000099>
20197 14:04:16 read(99, <unfinished ...>
20197 14:04:16 <... read resumed> 0x7f4dc01b4170, 64966) = -1 EAGAIN (Resource temporarily unavailable) <0.001609>
--

Шуканий дескриптор 99.

Подивимося, скільки було читань з цього дескриптору. Підготуємо дані для gnuplot у вигляді часу (посекундна агрегація) і кількості викликів read за цю секунду.

$ grep 'read(99,' strace_p5_20197 | cut -f2 -d' ' | uniq -c | awk '{$1=$1};1' > data.txt

Побудував графік, і вийшло таке...

Дивно, кількість читань впало, але вони не зникли повністю. Наблизивши графік, 14:16:35 — 14:16:45 бачимо проблеми.

По прямій лінії між точками роблю висновок, що читань не було в цьому інтервалі. Якщо не було читань, то і не було записів споживачам, наприклад, того ж транскодеру. Тим не менше вирішив перевірити розподіл read і write по всьому треду.

Графік дивний. Кількість читань могло впасти через відключення стримерів. Тред перестав би їх процессить, і при наступному підключенні читання сокетів могло потрапити в інший тред. Але дивним здалося те, що при падінні операцій читання на порядок операції запису навіть підросли, і розкид викликів знизився: чим більше читань, тим більше коливань по осі Y на графіку між сусідніми часовими інтервалами.

Далі grep, sed і awk мене не вистачило. Та чого там гріха таїти, всією душею ненавиджу sed і awk з їх огидним синтаксисом. Настав час ще трохи пописати на JS. Я накидав код, який парсити весь лог strace для треда і для кожного файлового дескриптора вважає кількість читань, записів, кількість записаних і прочитаних байтів. Код на GitHub , там же приклад скрипта для gnuplot для побудови.

На першому графіку — сумарний час виконання read/write виклику для конкретного файлового дескриптора, просуммированное за інтервал в 1 секунду. На другому графіку відображена сума прочитаних байтів за інтервал в 1 секунду для кожного файлового дескриптора.

Дескриптори, не пов'язані з RTMP потоками, я виключив. Туди потрапили всякі пінги наявності потоку і т. д. Вони істотно не впливають на загальну картину.

Сплески exec time для read на fd=99 до 18 мс корелюють з інтенсивним читанням. Прочитав цей fd в ту секунду 380 Кб. 18 мс на 380 Кб. Не фонтан, звичайно, але і не дуже плачевно. Принаймні, явно не в читаннях справу.

А що з записами?

Воу-воу! Це що, для fd=165 вимагалося більше 200 мс кожну секунду з 14:10:00 для того, щоб відправляти по 300 Кб? Інші не краще. На графіку добре видно, що підключення нових слухачів (тих, кому write виклики шлють контент) викликає деградацію в інших викликів write? А відключення, як було після 14:02:00, зменшує таймінг?

Тоді можна припустити, що із-за повільного write не встигають у рамках треда вирушати дані у всі сокети. А Wowza ще й читає контент...

До цього моменту TL дописав код Wowza модулів і поставив логування все, що тільки можливо, у місцях, де є synchronized блоки та інші блокування. Блокування в модулях не були виявлені.

Два незалежних підтвердження, що не у блокуваннях справу. Треба розбиратися, що відбувається з ОС.

Наступна гіпотеза — крива настройка ОС.

Відразу скажу, що у нас залізо все своє. Ніякі клауды не дадуть такого контролю і вартості, тому тільки bare metal, тільки хардкор.

Починаємо перебирати все, що може впливати на працездатність системи:

Тюнінг стека TCP. Хороші матеріали по цій темі — раз , два . Виміри в одній зі статей свідчать, що тюнінг може дати покращення результатів вимірів в 4-5 разів.
Interrupts (hardware interrupts and software interrupts). Можливо, NIC TX/RX буфер переповнюється, і відбувається повторна доставка.
Спостереження за переполнениями буферів NIC, ethtool і т. д.
Huge pages — за замовчуванням CentOS аллоцирует пам'ять блоками по 4K. Якщо включити Huge Pages, то ефективність підвищиться. Були виключені зовсім.

З тюнінгом TCP зробили все що можна, підняли буфера до рекомендованих значень, провели теоретичний розрахунок навіть. Та й всю ОС переглянули критичним налаштувань. Рекомендую до прочитання статтю від RedHat про тюнінг і налаштування для роздачі відео від знайомого проекту .

Знайшли неналаштовані шматки, наприклад, ліміт на відкриті файли, встановлений в дефолтні 1024. Результату значного це не дало, потім перейшли до тюнінгу CPU affinity, буферам NIC і т. п.

Окремо поверхнево пройдемося по interrupts, буферам NIC (network interface controller) і процесу доставки даних від NIC до додатка.
Мережева карта (NIC) має мікропроцесором і може використовувати інтегровану пам'ять для буферів, або RAM системи.

Більшість інтегрованих карт дешевше сотень доларів використовують RAM і аллоцируют пам'ять прямо в RAM. Наші карти входять у число таких, бо в тексті далі виходимо з того, що мова йде про NIC без власної пам'яті. При реєстрації драйвера NIC виділяється пам'ять під буфери на відправку (TX ring buffer) і отримання даних (RX ring buffer).

Кількість буферів визначається параметрами, може тюниться, а сучасні карти підтримують сотні і тисячі таких буферів. Важливо розуміти, що буфера кільцеві. Якщо один буфер має розмір у 200 байт, і дані з буфера не прочитані та не оброблені, то наступна порція даних перетрет «старі» дані в буфері. Таким чином, якщо не вичитуються дані з буфера NIC, то вони будуть витіснені, і, як наслідок, неприємна поведінка гарантовано.

У більшості компонентів комп'ютерів є сигнальні протоколи, і NIC не виняток. Коли NIC фіксує отримання даних і записує в RX buffer ці дані, то NIC повинен повідомити ядро про надходження нових даних. Для цього і використовуються IRQ (Interrupt ReQuest). NIC шле IRQ, CPU обробляє цей IRQ і викликає код, який віднімає дані з RX buffer і передасть далі на обробку. Далі пакети пройдуть вже не через код драйверів, а через network підсистеми ядра, правильно розіб'ються за протоколами, буде визначено додаток-одержувач, і вже в буфера сокетів будуть доставлені дані. Додатком залишиться прочитати дані з цього сокета.

Повернемося на крок назад. Як NIC запише дані в буфер RAM? Ще років 10 тому NIC вимагалося мати власну пам'ять і за запитом ядра віддавати дані, що знаходяться в ній. Зараз скрізь використовується DMA (Direct Memory Access) — технологія, яка дозволяє робити прямі звернення до виділеної області RAM безпосередньо зі сторонніх пристроїв, минаючи CPU, системні виклики і т. д. Доступ до цих ділянок пам'яті і CPU, і, як наслідок, у ядра. Тому час між отриманням даних NIC, записом в RAM та отриманням цих даних ядром зменшилася, що позитивно позначилося на продуктивності. Резюмую: NIC пишуть дані в RAM допомогою DMA, а потім NIC генерує IRQ-сигнал, щоб ядро могло обробити ці дані.

IRQ, про яких йшла мова вище, є hardware interrupts і змушують CPU зупиняти виконання коду і перемикатися на обробку переривання. Коли в системі багато трафіку, то NIC буде тисячі разів в секунду генерувати IRQ і змушувати process switching, важку операцію. Тому з'явилося поліпшення, був придуманий механізм softIRQ і включений до ядра ОС, а для драйверів NIC був розроблений NAPI -механізм.

Драйвера, які підтримують NAPI, тепер можуть надати poll-функцію, яку буде використовувати ядро для опитування буферів. Ядро ж реєструє ці poll-функції і запускає їх в окремих тредах. Вони відображаються в top як ksoftirqd. Коли прилітає самий перший пакет пристрою з NAPI і SoftIRQ підтримкою, NIC пошле IRQ. IRQ викличе обробник, який включить механізм polling. Як тільки він включений, треди ksoftirqd будуть з певною частотою опитувати буфера і при необхідності запускати обробку пакетів, що знаходяться в них. При цьому поки відбувається polling, відключається обробка IRQ. Такий підхід дозволяє істотно економити ресурси і не допускати перемикань контексту. Якщо пакетів стане критично мало, то CPU буде даремно намагатися перевіряти наявність даних і даремно витрачати процесорний час. Щоб і тут заощадити, відбувається відключення polling і включення штатних IRQ. Коли потік пакетів стане високим, знову відбудеться включення polling.

Окремий тюнінг може бути проведений з CPU affinity , що дозволяє прив'язати процеси ksoftirqd до певного CPU/ядрам, що збільшить локальність кешу CPU і пропускну здатність.

Якщо тема з IRQ, SoftIRQ і поведінкою ядер в real-time системах зацікавила, то рекомендую просто відмінний цикл публікацій для деталізації того, що відбувається під капотом ядра і драйверів NIC, а ще оглядові презентації номер 1 і номер 2 .

Фух, теоретична частина закінчена, опустимося на землю.

Рішення

Тулзой ethtool можна подивитися налаштування NIC, версію драйвера і поспостерігати за статистикою.

# ethtool -i eth1

driver: tg3
версія: 3.137
firmware-version: FFV7.8.16 bc 5720-v1.32

# ethtool -g eth1

Ring parameters for eth1:
Pre-set maximums:
RX: 2047
RX Mini: 0
RX Jumbo: 0
TX: 511
Current hardware settings:
RX: 200
RX Mini: 0
RX Jumbo: 0
TX: 511

У висновку вище видно, що драйвер tg3, а картка сервері Broadcom 5720 1Gb. Збентежив RX розмір буфера, що дорівнює 200 байтам. Як-то біса мало, потюнили і це. TX буфера теж малі. Найсумніше, що для TX максимальне значення дорівнює 511, і воно не змінюється без перезбирання драйвера з исходников .

Масла у вогонь підливала статистика, хотілося б бачити 0...

25673 packet

Опубліковано: 28/11/19 @ 11:00
Розділ Блоги

SEO Блог