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

[Про автора: Дмитро Меньшиков — 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-шаром. На це вказували і фризи, які були індикатором того, що не надходять дані потоку, і обривалися не відразу всі потоки, а тільки частину.

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

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

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

  1. Винен дата-центр, і проблема у них, десь втрати на каналі.
  2. Винні адміни, маршрутизатор або сервера.
  3. Винна 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 в такому порядку:

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

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

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

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

За 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, тільки хардкор.

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

  1. Тюнінг стека TCP. Хороші матеріали по цій темі — раз , два . Виміри в одній зі статей свідчать, що тюнінг може дати покращення результатів вимірів в 4-5 разів.
  2. Interrupts (hardware interrupts and software interrupts). Можливо, NIC TX/RX буфер переповнюється, і відбувається повторна доставка.
  3. Спостереження за переполнениями буферів NIC, ethtool і т. д.
  4. 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 packets pruned from receive queue because of socket buffer overrun
173905 packets collapsed in receive queue due to low socket buffer

Для оцінки продуктивності мережі і стека TCP існує багато інструментів. Найвідоміший, мабуть, — iperf .

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

>iperf3 -c hostname -u -b9G -w2m -i2
[ ID] Interval Transfer Bandwidth Total Datagrams
[ 4] 0.00-2.00 sec 2.07 GBytes 8.91 Gbits/sec 248878
[ 4] 2.00-4.00 sec 2.08 GBytes 8.91 Gbits/sec 249020
[ 4] 4.00-6.00 sec 2.11 GBytes 9.07 Gbits/sec 253434
[ 4] 6.00-8.00 sec 2.11 GBytes 9.08 Gbits/sec 253730
[ 4] 8.00-10.00 sec 2.03 GBytes 8.73 Gbits/sec 244013
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval Transfer Bandwidth Jitter Lost/Total Datagrams
[ 4] 0.00-10.00 sec 10.4 GBytes 8.94 Gbits/0.008 sec ms 0/1248863 (0%)
[ 4] Sent 1248863 datagrams

Ми поганяли і його, він показав плюс-мінус прийнятні дані, але був ряд недоліків: багатопоточність, відсутність тонких налаштувань параметрів з'єднань. Достовірним назвати такий замір було не можна.

До цього моменту я розібрав вплив самого strace на заміри. Я розумів, що він може вносити деградацію на час замірів та їх спотворювати. Тому були знайдені підтвердження і сферичні цифри у вакуумі . До того ж даних не вистачало, і хотілося залізти на рівень профайлінгу ядра Linux. Настала ера perf.

З perf відразу ж зіткнулися з потоком проблем:

1) Відсутність підтримки в ядрах OpenVZ 2.6.32, які ми використовували в продакшне для віртуалізації debuffs.

Окей, шукаємо опцію, що включає debuffs, вона була знайдена в vzkernel-debug ядрі.

2) Місця в/не вистачило на залізяках, щоб поставити vzkernel-debug.

Окей, розширюємо місце, адміни шаманять.

3) Місце є, ядро поставлено, але навіть з perf_event_paranoid не можна запустити в контейнері.

Окей, ставимо руками Wowza на хардноду і намагаємося запустити.

4) Не заводиться, не бачить доступних для спостереження функцій.

Окей, пересобираем ядро і шляхом проб і помилок знаходимо весь пул налаштувань, які йому потрібні. Ось він:

CONFIG_FRAME_POINTER = and
CONFIG_BOOT_PRINTK_DELAY = and
CONFIG_FAULT_INJECTION = and
CONFIG_FAILSLAB = y

Мої нерви закінчилися на кроці 2, і поки адміни билися з проблемами, я підняв на AWS EC2 два dedicated сервера в одному і тому ж az для своїх експериментів, адже досвіду з perf у нас не було.

Головним джерелом інформації в Мережі perf є Brendan Gregg, і в блозі у нього найцінніша база знань . Озброївшись статтею Netflix про профайлинге з допомогою perf-додатків на Java, почав розбиратися з Wowza на EC2.

Поки наші роботи синхронізувалися, я вже встиг погратися з perf на EC2 і отримав практичний досвід роботи з ним. Почали робити заміри на нашому залозі.

Чи варто говорити, що інструменти навколо perf і далі продовжували падати? Я вже змирився, що низка труднощів і невдач переслідує нас. Треба було освятити сервера, чи що.

# /root/perf-map-agent/bin/perf-java-top 11139
співвідношення вага: Segmentation fault
-------- backtrace --------
perf[0x4ee551]
/lib64/libc.so.6(+0x32510)[0x7f339968c510]
perf[0x433e7a]
перфорація(cmd_top+0x101e)[0x434fde]
perf[0x467503]
перфорація(main+0x649)[0x468279]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7f3399678d1d]
perf[0x41b839]

Коли сталося диво, і perf зібрав статистику по одному з проблемних ingest-серверів, ми побачили наступне.

Картина по всім процесам:

Картина по самому споживає ресурси Java-процесу:

На графіку видно виклики функцій драйвера NIC (tg3). Наприклад, функція відправки tg3_start_xmit. Увагу привернув виклик debug_dma_map_page, зроблений з tg3_start_xmit. Судячи по споживанню, найбільше отъела ця гілка виконання. Всередині ще видно save_stack_trace, print_context_stack і так далі. Ми не то, щоб ми знали код драйверів, які використовуємо, але нічого не залишалося, як засукати рукави і занурити руки в драйвера tg3.

А як справи на AWS EC2 серверах? Щоб мати еталон для порівняння, були підняті сервера з хорошою мережевий продуктивністю, піднята Wowza, а трафік відправлений на цей сервер. Під навантаженням зняті показники perf.

Як видно, ніяких проблем не спостерігається. Додаткових важких викликів всередині xennet_start_xmit немає (xennet — це paravirtualized network interface для гіпервізора Xen, віртуальні машини в EC2 на базі Xen працюють). До речі, на EC2 танців з бубном не знадобилося, perf завівся відразу.

Треба копати під драйвер. Код драйвера знаходиться в ядрі; підібравши версію vzkernel, яка була у нас, приступив до аналізу.

У драйверах біля коду tg3_start_xmit були знайдені коментарі:

/* The EPB bridge inside 5714, 5715, and 5780 and any
 * device behind the EPB cannot support DMA addresses > 40-bit.
 * On 64-bit systems with IOMMU, use 40-bit dma_mask.
 * On 64-bit systems without IOMMU, use 64-bit and dma_mask
 * do DMA address check in tg3_start_xmit().
*/

...

 /* Need to make the tx_cons update visible to tg3_start_xmit()
 * before checking for netif_queue_stopped(). Without the
 * memory barrier, there is a small possibility that tg3_start_xmit()
 * will miss it and cause the queue to be stopped forever.
*/

Подальший розбір дав наступне:

Володіючи цим набором даних, ми вирішили підібрати NIC виходячи з наявності трекінгу помилок DMA. Sic! Такими були драйверами ixgb і ixgbe, Intel картки на 10G. З включеним дебагом вони будуть писати інфо в /sys/kernel/debug/ixgb або /sys/kernel/debug/ixgbe. При неможливості замапить регіон TX buffer буде здійснено запис в dmesg: «TX DMA map failed». ethtool -c ж буде виводити статистику rx_page_failed і tx_page_failed. Хоч щось.

За збігом обставин, картка Intel X540-T2 була на складі у дата-центру, і драйвера підходили. Залишалося її оперативно встановити, накотити нове ядро Linux і продовжити експерименти. Перша хороша новина? Пфф, зараз. Дата-центр профакапил і встановив карту Intel I350-T2. Довелося її міняти. Потім DRAC (baseboard management controller від Dell) не завівся, і довелося розбиратися, що не так насетапали. В моїй історії хороших новин не буває!

Коли підняли ядро з правильної карти, результати вийшли такі.

Налаштування бадьоріше у X540:

[root@stream5.am ~]# ethtool -g eth0
Ring parameters for eth0:
Pre-set maximums:
RX: 4096
RX Mini: 0
RX Jumbo: 0
TX: 4096

Current hardware settings:
RX: 2048
RX Mini: 0
RX Jumbo: 0
TX: 512

На перший погляд, зріз по всім процесам виглядає так само. Якщо копнути під найважчий Java-процес, то побачимо:

Зовні відмінності помітні. Я вже відкоркував шампанське, проблема вирішена! Через кілька годин знову почали спостерігатися фризи.

Вирішено було провести виміри продуктивності мережі, поки нова карта встановлена.

Для наших експериментів використовувався sockperf . Компанія, яка його розробляє, — відомий гравець на ринку low latency NIC, і свої інструменти вони пристосували для розширеного аналізу. Головний плюс, що з sockperf можна задати параметри для тесту в точності, як у Wowza: TCP_NODELAY, epoll_wait таймаут, писати дані з N байт.

TCP_NODELAY вимикаєалгоритм Нейгла . Якщо цей алгоритм включений, то можливе збільшення latency.

А подолбаться з встановленням того ж sockperf теж довелося. У Epel бажная версія, необхідно було перезбирати руками. Це все час, якого немає.

Варто зазначити, що для максимальної достовірності тести проводилися між проблемними ingest і транскодером, щоб все було чесно, маршрути були ті ж, і не виявилося, що налаштування мережі криві, і на інших машинах проблему не побачимо.

[root@stream5.am ~]# echo "T:10.2.1.152:11110" > s.list

[root@stream5.am ~]# sockperf ping-pong -f s.list -F e -t 10 --timeout 1 -m 512 --tcp-avoid-nodelay --nonblocked --tcp-skip-blocking-send --mps 10000

sockperf: == version # ==
sockperf[CLIENT] send on:sockperf: using epoll() to block on socket(s)
[ 0] IP = 10.2.1.152 PORT = 11110 # TCP
sockperf: Warmup stage (sending a few dummy messages)...

sockperf: Starting test...
sockperf: Test end (interrupted by timer)
sockperf: Test ended

sockperf: [Total Run] RunTime=10.450 sec; SentMessages=59403; ReceivedMessages=59402
sockperf: ========= Printing statistics for Server No: 0
sockperf: [Valid Duration] RunTime=10.000 sec; SentMessages=56984; ReceivedMessages=56984

sockperf: ====> avg-lat= 87.675 (std-dev=20.998)
sockperf: # dropped messages = 0; # duplicated messages = 0; # out-of-order messages = 0
sockperf: Summary: Latency is 87.675 usec
sockperf: Total 56984 observations; each percentile contains 569.84 observations
sockperf: ---> observation = 2431.621
sockperf: ---> percentile 99.999 = 1964.399
sockperf: ---> percentile 99.990 = 903.950
sockperf: ---> percentile 99.900 = 171.824
sockperf: ---> percentile 99.000 = 117.329
sockperf: ---> percentile 90.000 = 100.605
sockperf: ---> percentile 75.000 = 91.773
sockperf: ---> percentile 50.000 = 85.400
sockperf: ---> percentile 25.000 = 79.114
sockperf: ---> observation = 74.393

[root@stream5.am ~]# sockperf ping-pong -f s.list -F e -t 10 --timeout 1 -m 14 --tcp-avoid-nodelay --nonblocked --tcp-skip-blocking-send --mps 10000

sockperf: == version # ==
sockperf[CLIENT] send on:sockperf: using epoll() to block on socket(s)
[ 0] IP = 10.2.1.152 PORT = 11110 # TCP
sockperf: Warmup stage (sending a few dummy messages)...
sockperf: Starting test...
sockperf: Test end (interrupted by timer)
sockperf: Test ended
sockperf: [Total Run] RunTime=10.450 sec; SentMessages=69431; ReceivedMessages=69430
sockperf: ========= Printing statistics for Server No: 0
sockperf: [Valid Duration] RunTime=10.000 sec; SentMessages=66536; ReceivedMessages=66536
sockperf: ====> avg-lat= 75.076 (std-dev=20.043)
sockperf: # dropped messages = 0; # duplicated messages = 0; # out-of-order messages = 0
sockperf: Summary: Latency is 75.076 usec
sockperf: Total 66536 observations; each percentile contains 665.36 observations
sockperf: ---> observation = 1521.846
sockperf: ---> percentile 99.999 = 1450.021
sockperf: ---> percentile 99.990 = 914.075
sockperf: ---> percentile 99.900 = 223.133
sockperf: ---> percentile 99.000 = 100.173
sockperf: ---> percentile 90.000 = 84.808
sockperf: ---> percentile 75.000 = 80.184
sockperf: ---> percentile 50.000 = 70.178
sockperf: ---> percentile 25.000 = 68.719
sockperf: ---> observation = 66.878

Перший тест відправляв пакети по 512 байт, а другий по 14 байт. Налаштування були взяті з поведінки реального програми — те, що заміряли ще strace. Результат середньої затримки — 87.675 usecі 75.076 usecвідповідно.

Порившись в інтернеті, виявив результати вимірів на EC2 инстансы, які плюс-мінус відповідають результатам, отриманим на Intel X540-T2 і Centos 7.

Фризи є, але проблема не в мережі. Проблема з Centos 6 і Broadcom 5720 явно була, її усунули, але це не допомогло глобально.

Наступна гіпотеза? Немає гіпотези! Ми всі помремо!

Експерименти, описані вище, зайняли не один день. Адже введення і виведення серверів для експериментів вимагає виведення їх на обслуговування, очікування годинами, поки не піде навантаження, введення, очікування... Ціла спецоперація!

Поки експериментатори висували і спростовували гіпотези, був доопрацьований наш супермодуль на Node.js video-quality-tools , доступний на GitHub.

Завданняvideo-quality-tools полягала в real-time моніторингу за відеопотоком, аналізі технічних характеристик: FPS, bitrate. Модуль дозволяє контролювати частоту створення кадрів на стороні стримера (інакше кажучи, на encoder), заміряти фактичні значення після отримання по мережі. За допомогою такої механіки можна зрозуміти, де деградація мережі, а де деградація на стороні користувача, наприклад, CPU перевантажений у користувача.

Модуль був успішно використаний, була піднята Grafana з InfluxDB, і почався збір метрик з ingest-серверів в розрізі кожного потоку на ingest. Це куди зручніше, ніж використовувати gnuplot, до того ж повний real-time і можливість моментально реагувати.

Grafana почала показувати FPS (frames per seconds), як вони виходили модулем (не на енкодери).

З урахуванням одного ingest на Centos 7 з новою картою з'явилася можливість порівняти один і той же потік, який кодується одним і тим же обладнанням, з тієї ж локації, але на двох різних версіях ядра і мережевих карт.

Centos 7 вів себе однозначно краще: немає осідань FPS в 0, не було різких стрибків FPS вгору. Потім був словлен фриз на Centos 7.

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

Під час фризів і дропов деякі потоки відчували себе добре і виглядали приблизно як на графіку нижче.

Але, судячи з Kibana, епізодичний характер розривів присутній. Найцікавіше, що він як починається раптово, так несподівано і закінчується.

Тривають експерименти з ядрами, дебаг і не дебаг, vzkernel і голе ядро, танці, веселощі...

Зайшли в глухий кут. Залишається зробити крок назад.

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

Раптово, Chief Admin за якоюсь потребою почав HTTP смикати Wowza на origin шарі і здивувався затримку відповіді.

[root@w-o-8.am /]# time curl vss-w-o-3:1935
real 0m0.109s
user 0m0.003s
sys 0m0.001s

[root@w-o-8.am /]# time curl vss-w-o-3:1935
real 0m7.008s
user 0m0.003s
sys 0m0.001s

Спершу 100 мс, а потім 7 секунд. Були помічені фризи, і можна було аналізувати логи з транскодеров.

Parsed protocol: 0
Parsed host : 10.2.1.174
Parsed app : origin
RTMP_Connect0, failed to connect socket. 4 (Interrupted system call)
rtmp://10.2.1.174/origin/117687be99efe796800e098e36b79f7e_bc2_hd: Unknown error occurred
[AVIOContext @ 0x18d9cc0] Statistics: 152844 read bytes, 0 seeks
RTMP_SendPacket: fd=5, size=34
Invoking deleteStream
Exiting normally, received signal 15.

video-quality-tools був прикручений в origin, і стало видно справжній треш.

Чорт, це ж обриви на стороні origin! Пазл моментально склався:

Переключивши увагу на origin, спробували зняти інформацію strace, адже perf вимагав перезбирання ядра і винесення експериментів на хардноду з виртуалки. strace нам не допоміг, бо в моменти його запуску деградація починалася моментально: занадто великий негативний impact давав сам strace.

Ось як проявлялося включення strace:

Вся надія залишалася на VisualVM . З його допомогою можна профілювати Java-додатки. Щоб профайлер підключився, потрібно трохи переналаштувати Wowza, підключитися до неї профайлером і працювати... працювати...

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

Видно, що з моменту старту origin пройшло всього 25 хвилин, але весь час плавала CPU утилізація і heap зростав. В певний момент він доходив до трешхолда, і включався GC (garbage collector). Поки GC буйствував, відбувався stop the world , і все завмирало. Ось де була причина!

Ми використовували Wowza в продакшне кілька років до цього, проводили навантажувальні тести і отримували нормальні результати. Деякі тести днями ганялися на ній. Такої поведінки раніше помічено не було. GC до цього не зупиняв виконання так часто, пам'ять так швидко не росла. Щось не так з origin.

У Wowza реалізовані MBeans, тому, спостерігаючи за різними змінними, встановили причину зростання споживання пам'яті.

Цією причиною виявилися RTMP з'єднання від edge-серверів. При цьому edge і origin були побудовані на базі Wowza!

На зображенні вище видно монотонний приріст RTMP-з'єднань. Іноді за хвилину могло прирости 50 нових сполук, і вони відразу ж закривалися. Але іноді Wowza-edge-сервера сходили з розуму і Wowza починала генерувати тисячі RTMP-з'єднань на origin. Системи в цьому особливої не було.

З допомогою tcpdump було встановлено, що Wowza-edge намагався в циклі підключитися на origin, щоб отримати потік, якого вже на origin немає. Бізнес-логіка змушувала забувати про таких потоках і не намагатися підключитися, але Wowza ігнорувала це, і все одно підключалася і підключалася. Origin, який брав на себе удар, встановлював з'єднання, обробляв запити і відповідав, що потоку немає, закриваючи з'єднання... і відразу ж ловив тисячі нових таких запитів.

Коли потік сполук вщухав, незрозуміло з якої причини, то все устаканивалось і продовжувало працювати... до наступного шквалу. Навантаження розподілилася так чітко, що наш моніторинг не помітив відхилень по CPU usage, і ми навіть не дивилися в сторону origin.

Порадившись, як діяти далі, враховуючи минулий досвід спілкування з саппортом і пошуки проблем, ми вирішили:

Вибір для швидкого кандидата упав на nginx-rtmp-module . Це далеко не ідеальний кандидат для заміни, модуль погано працює з багатопоточністю і лімітує обсяги трафіку, так і кількість потоків, але це краще, ніж нічого.

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

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

Рекомендуємо:

5 книжок про роботу мозку від Олексія Молчановського, керівника магістратури з Data Science в УКУ
Збірка домашнього 3D-принтера своїми руками: рекомендації з особистого досвіду
Оцінка трудомісткості розробки проектів. Частина 2
Висновок реалізацій інтерфейсів в Scala c бібліотекою Shapeless
Java дайджест #45: Micronaut і Quarkus, відео з Devoxx Belgium 2019