Кілька років тому Kubernetes в офіційному блозі GitHub. З того часу він став стандартною технологією для розгортання сервісів. Тепер Kubernetes управляє значною частиною внутрішніх та громадських служб. Оскільки наші кластери зросли, а вимоги до продуктивності стали жорсткішими, ми помітили, що у деяких службах на Kubernetes спорадично з'являються затримки, які не можна пояснити навантаженням самого додатка.
По суті, у додатках відбувається ніби випадкова мережева затримка до 100 мс і більше, що призводить до тайм-аутів або повторних спроб. Очікувалося, що служби зможуть відповідати на запити набагато швидше за 100 мс. Але це неможливо, якщо саме з'єднання забирає стільки часу. Окремо ми спостерігали дуже швидкі запити MySQL, які мали займати мілісекунди, і MySQL справді справлялася за мілісекунди, але з погляду запитуючого програми відповідь займав 100 мс або більше.
Відразу стало зрозуміло, що проблема виникає лише при з'єднанні з вузлом Kubernetes, навіть якщо виклик надходив ззовні Kubernetes. Найпростіше відтворити проблему в тесті , який запускається з будь-якого внутрішнього хоста, тестує службу Kubernetes на певному порту та спорадично реєструє велику затримку. У цій статті розглянемо, як нам удалося відстежити причину цієї проблеми.
Усуваємо зайву складність у ланцюжку до збою
Відтворивши той самий приклад, ми хотіли звузити фокус проблеми і видалити зайві шари складності. Спочатку у потоці між Vegeta та pod'ами на Kubernetes було надто багато елементів. Щоб визначити глибшу мережну проблему, потрібно виключити деякі з них.
Клієнт (Vegeta) створює TCP-з'єднання з будь-яким вузлом у кластері. Kubernetes працює як оверлейна мережа (поверх існуючої мережі дата-центру), яка використовує тобто інкапсулює IP-пакети оверлейної мережі всередину IP-пакетів дата-центру. При підключенні до першого вузла виконується перетворення мережевих адрес. (NAT) з відстеженням стану для перетворення IP-адреси та порту вузла Kubernetes в IP-адресу та порт в оверлейній мережі (зокрема, pod'а з додатком). Для пакетів, що надійшли, виконується зворотна послідовність дій. Це складна система з великою кількістю станів та безліччю елементів, які постійно оновлюються та змінюються у міру розгортання та переміщення служб.
Утиліта tcpdump у тесті Vegeta дає затримку під час рукостискання TCP (між SYN та SYN-ACK). Щоб усунути цю зайву складність, можна використовувати hping3 для простих пінгів пакетами SYN. Перевіряємо, чи є затримка в пакеті у відповідь, а потім скидаємо з'єднання. Ми можемо відфільтрувати дані, увімкнувши тільки пакети більше 100 мс, і отримати більш простий варіант відтворення проблеми, ніж повний тест мережевого рівня 7 у Vegeta. Ось "пінги" вузла Kubernetes з використанням TCP SYN/SYN-ACK на "порту вузла" служби (30927) з інтервалом 10 мс, відфільтровані за найповільнішими відповідями:
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms
len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms
Відразу може зробити перше спостереження. За порядковими номерами та таймінгами видно, що це не одноразові затори. Затримка часто накопичується, і зрештою обробляється.
Ми хочемо з'ясувати, які компоненти можуть бути причетні до появи затору. Може, це якісь із сотень правил iptables у NAT? Або якісь проблеми з тунелюванням IPIP у мережі? Один із способів перевірити це – перевірити кожен крок системи, виключивши його. Що станеться, якщо прибрати NAT та логіку брандмауера, залишивши лише частину IPIP:
На щастя, Linux дозволяє легко звертатися безпосередньо до оверлейного шару IP, якщо машина входить до тієї ж мережі:
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms
len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms
Судячи з результатів, проблема все ще залишається! Це виключає iptables та NAT. Значить, проблема у TCP? Подивимося, як іде звичайний ICMP-пінг:
theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms
len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms
len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms
len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms
len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms
len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms
len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms
Результати свідчать, що проблема не зникла. Можливо, це IPIP тунель? Давайте ще спростимо тест:
Усі пакети вирушають між цими двома хостами?
theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms
len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms
len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms
len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms
len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms
Ми спростили ситуацію до двох вузлів Kubernetes, що відправляють один одному будь-який пакет, навіть пінг ICMP. Вони все одно бачать затримку, якщо цільовий хост є «поганим» (деякі гірші за інші).
Тепер останнє питання: чому затримка виникає лише на серверах kube-node? І вона відбувається, коли kube-node є відправником чи одержувачем? На щастя, це теж досить легко з'ясувати, відправляючи пакет із хоста за межами Kubernetes, але з тим самим «відомим поганим» одержувачем. Як бачимо, проблема не зникла:
theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms
len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms
Потім виконаємо ті ж запити від попереднього вихідного kube-node до зовнішнього хоста (що виключає вихідний хост, оскільки пінг включає компонент RX, так і TX):
theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
^C
--- 172.16.33.44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms
Вивчивши захоплення пакетів із затримкою, ми отримали додаткову інформацію. Зокрема, що відправник (внизу) бачить цей тайм-аут, а одержувач (вгорі) не бачить - див.
Крім того, якщо подивитися на різницю в порядку пакетів TCP та ICMP (за порядковими номерами) на стороні одержувача, то пакети ICMP завжди надходять у тій самій послідовності, в якій вони були надіслані, але з різним таймінгом. У той самий час пакети TCP іноді чергуються, а частина їх застряє. Зокрема, якщо вивчити порти пакетів SYN, то на стороні відправника вони йдуть по порядку, а на стороні одержувача немає.
Є тонка різниця у тому, як сучасних серверів (як у дата-центрі) обробляють пакети, що містять TCP або ICMP. Коли надходить пакет, мережний адаптер «хешує його з'єднання», тобто намагається розбити з'єднання по чергах і відправити кожну чергу на окреме процесорне ядро. Для TCP цей хеш включає як вихідний, так і кінцевий IP-адресу і порт. Інакше кажучи, кожне з'єднання хешується (потенційно) по-різному. Для ICMP хешуються лише IP-адреси, оскільки немає портів.
Ще одне нове спостереження: протягом цього періоду ми бачимо затримки ICMP на всіх комунікаціях між двома хостами, а TCP не має. Це говорить нам про те, що причина, ймовірно, пов'язана з хешуванням черг RX: майже напевно затор виникає в обробці пакетів RX, а не надсилання відповідей.
Це виключає зі списку можливих причин надсилання пакетів. Тепер ми знаємо, що проблема обробки пакетів знаходиться на стороні прийому на деяких серверах kube-node.
Розбираємося з обробкою пакетів у ядрі Linux
Щоб зрозуміти, чому проблема виникає у одержувача на деяких серверах kube-node, давайте подивимося, як ядро Linux обробляє пакети.
Повертаючись до найпростішої традиційної реалізації, мережева карта отримує пакет та відправляє ядру Linux є пакет, який потрібно обробити. Ядро зупиняє іншу роботу, перемикає контекст на обробник переривань, обробляє пакет, а потім повертається до поточних завдань.
Це перемикання контексту відбувається повільно: можливо, затримка була непомітна на 10-мегабітних мережевих картах у 90-ті роки, але на сучасних картах 10G з максимальною пропускною здатністю 15 мільйонів пакетів на секунду кожне ядро маленького восьмиядерного сервера може перериватися мільйони разів на секунду.
Щоб не займатися постійною обробкою переривань, багато років тому в Linux додали : мережний API, який використовують усі сучасні драйвери для підвищення продуктивності на високих швидкостях. На низьких швидкостях ядро все ще приймає переривання від карти мережі старим способом. Як тільки приходить достатня кількість пакетів, яка перевищує поріг, ядро відключає переривання і натомість починає опитувати мережевий адаптер і забирати пакети порціями. Обробка виконується в softirq, тобто в після системних викликів і апаратних переривань, коли ядро (на відміну користувальницького простору) вже запущено.
Це набагато швидше, але викликає іншу проблему. Якщо пакетів занадто багато, то весь час йде на обробку пакетів з мережевої карти, а процеси простору користувача не встигають фактично спустошити ці черги (читання з TCP-з'єднань і т. д.). Зрештою черги заповнюються, і ми починаємо відкидати пакети. Намагаючись знайти баланс, ядро встановлює бюджет на максимальну кількість пакетів, що обробляються у контексті softirq. Як тільки цей бюджет перевищено, прокидається окремий потік ksoftirqd (ви побачите один з них у ps для кожного ядра), який обробляє ці softirq за межами звичайного шляху syscall/interrupt. Цей потік планується за допомогою стандартного планувальника процесів, який намагається справедливо розподіляти ресурси.
Вивчивши, як ядро обробляє пакети, можна побачити, що є певна ймовірність появи заторів. Якщо виклики softirq надходять рідше, пакетам доведеться деякий час чекати на обробку в черзі RX на мережній карті. Можливо, це відбувається через якесь завдання, що блокує ядро процесора, або щось інше заважає ядру запускати softirq.
Звужуємо обробку до ядра чи методу
Затримки softirq — це лише припущення. Але воно має сенс і ми знаємо, що в нас спостерігається щось дуже схоже. Тому наступний крок – підтвердити цю теорію. І якщо вона підтвердиться, то знайти причину затримки.
Повернемося до наших повільних пакетів:
len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms
len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms
len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms
len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms
len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms
len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms
Як було обговорено раніше, ці пакети ICMP хешуються в одну чергу NIC RX і обробляються одним ядром CPU. Якщо ми хочемо зрозуміти роботу Linux, корисно знати, де (на якому ядрі CPU) і як (softirq, ksoftirqd) ці пакети обробляються, щоб відстежити процес.
Тепер настав час використовувати інструменти, які дозволяють у реальному часі відстежувати роботу ядра Linux. Тут ми використали . Цей набір інструментів дозволяє писати невеликі програми на C, які перехоплюють довільні функції в ядрі і буферизують події в програму Python користувача простору, яка може обробляти їх і повертати вам результат. Хуки для довільних функцій у ядрі — складна справа, але утиліта спроектована на максимальну безпеку і призначена для відстеження таких проблем продакшну, які непросто відтворити в середовищі тестування або розробки.
План тут простий: ми знаємо, що ядро обробляє ці пінги ICMP, тому поставимо хук на функцію ядра , яка приймає вхідний ICMP-пакет echo request і ініціює відправку ICMP-відповіді echo response. Ми можемо ідентифікувати пакет збільшення номера icmp_seq, який показує hping3 вище.
Код виглядає складним, але він не такий страшний, як здається. Функція icmp_echo передає struct sk_buff *skb: це пакет із запитом «echo request». Ми можемо відстежити його, витягнути послідовність echo.sequence (яка зіставляється з icmp_seq від hping3 выше), і відправити її в простір користувача. Також зручно захопити поточне ім'я процесу/ідентифікатор. Нижче наведено результати, які ми бачимо безпосередньо під час обробки пакетів ядром:
TGID PID PROCESS NAME ICMP_SEQ 0 0 swapper/11 770 0 0 swapper/11 771 0 0 swapper/11 772 0 0 swapper/11 773 0 0 swapper/11 774 20041 20086 775 swapper/0 0 11 776 swapper/0 0 11 777 spokes-report-s 0
Тут слід зазначити, що у контексті softirq процеси, які зробили системні виклики, відобразяться як процеси, хоча насправді це ядро безпечно обробляє пакети в контексті ядра.
З цим інструментом можемо встановити зв'язок конкретних процесів з конкретними пакетами, які показують затримку в hping3. Робимо простий grep на цьому захопленні для певних значень icmp_seq. Пакети, що відповідають вищевказаним значенням icmp_seq, були відзначені разом з їх RTT, які ми спостерігали вище (у дужках вказані очікувані значення RTT у пакетів, які ми відфільтрували через значення RTT менше 50 мс):
TGID PID PROCESS NAME ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoft q qd/11 1954 ** 89ms 76 76 ksoftirqd/11 1955 ** 79ms 76 76 ksoftirqd/11 1956 ** 69ms 76 76 ksoftirqd/11 1957 ** (59ms) 76 76 ksoftirqd/11 1958 ** (49ms) 76 76 ksoft qr irqd/ 11 1959 ** (39ms) 76 76 ksoftirqd/11 1960 ** (29ms) -- 76 76 cadvisor 11 1961 19 cadvisor 76 76 11 ksoftirqd/1962 9 10137 ** 10436ms 2068 10137 ksoftirqd/ 10436 2069 ** 76ms 76 11 ksoftirqd/2070 75 ** (76ms) 76 11 ksoftirqd/2071 65 ** (76ms) 76 11 ksoftirqd/2072 55 ** (76ms) 76 11 2073 ksoftirqd/45 76 ** (76ms)
Результати говорять нам про кілька речей. По-перше, всі ці пакети опрацьовує контекст ksoftirqd/11. Це означає, що для цієї конкретної пари машин ICMP-пакети хешувалися на ядро 11 у сторони, що приймає. Ми також бачимо, що при кожному заторі є пакети, які обробляються в контексті системного виклику cadvisor. потім ksoftirqd бере завдання на себе і відпрацьовує накопичену чергу: саме та кількість пакетів, що накопичилася після cadvisor.
Той факт, що безпосередньо перед цим завжди працює cadvisor, має на увазі його причетність до проблеми. За іронією, призначення — «аналізувати використання ресурсів та характеристики продуктивності запущених контейнерів», а не викликати цієї проблеми з продуктивністю.
Як і з іншими аспектами роботи контейнерів, це все вкрай передовий інструментарій, від якого можна очікувати проблем з продуктивністю в деяких непередбачених обставинах.
Що таке робить cadvisor, що гальмує чергу пакетів?
Тепер ми маємо досить хороше розуміння, як відбувається збій, який процес його викликає і на якому CPU. Ми бачимо, що через жорстке блокування ядро Linux не встигає вчасно запланувати ksoftirqd. І ми бачимо, що пакети обробляються у контексті cadvisor. Логічно припустити, що cadvisor запускає повільний syscall, після якого обробляються всі пакети, що накопичилися в цей час:
Це теорія, але як її перевірити? Що ми можемо зробити, то це простежити роботу ядра CPU протягом усього цього процесу, знайти точку, де відбувається перевищення бюджету на кількість пакетів і викликається ksoftirqd, а потім подивитися трохи раніше - що саме працювало на ядрі CPU безпосередньо перед цим моментом. Це як рентгенівський знімок CPU кожні кілька мілісекунд. Він виглядатиме приблизно так:
Зручно, що це можна зробити існуючими інструментами. Наприклад, із зазначеною періодичністю перевіряє задане ядро CPU і може генерувати графік викликів працюючої системи, включаючи простір користувача, і ядро Linux. Можна взяти цей запис і обробити його за допомогою невеликого форку програми від Брендана Грегга, який зберігає порядок трасування стеку. Ми можемо зберігати однорядкові трасування стека кожні 1 мс, а потім виділити та зберегти зразок за 100 мілісекунд перед тим, як у трасування потрапляє ksoftirqd:
# record 999 times a second, or every 1ms with some offset so not to align exactly with timers
sudo perf record -C 11 -g -F 999
# take that recording and make a simpler stack trace.
sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100
Ось результати:
(сотни следов, которые выглядят похожими)
cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_run
Тут багато чого, але головне, що ми знаходимо шаблон cadvisor перед ksoftirqd, який бачили раніше в трейсері ICMP. Що це означає?
Кожен рядок – це трасування CPU у певний момент часу. Кожен виклик вниз по стеку в рядку поділяється крапкою з комою. У середині рядків ми бачимо викликаний syscall: read(): .... ;do_syscall_64;sys_read; .... Таким чином, cadvisor витрачає багато часу на системний виклик read(), що відноситься до функцій mem_cgroup_* (верхня частина стека викликів/кінець рядка).
У трасуванні викликів незручно дивитися, що саме читається, тож запустимо strace і подивимося, що робить cadvisor, і знайдемо системні виклики довше 100 мс:
theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] <... futex resumed> ) = 0 <0.156784>
[pid 10432] <... futex resumed> ) = 0 <0.258285>
[pid 10137] <... futex resumed> ) = 0 <0.678382>
[pid 10384] <... futex resumed> ) = 0 <0.762328>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 658 <0.179438>
[pid 10384] <... futex resumed> ) = 0 <0.104614>
[pid 10436] <... futex resumed> ) = 0 <0.175936>
[pid 10436] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.228091>
[pid 10427] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.207334>
[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>
[pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 660 <0.159891>
[pid 10417] <... futex resumed> ) = 0 <0.917495>
[pid 10436] <... futex resumed> ) = 0 <0.208172>
[pid 10417] <... futex resumed> ) = 0 <0.190763>
[pid 10417] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576 <0.154442>
Як і можна було припустити, тут ми бачимо повільні виклики read(). З вмісту операцій читання та контексту mem_cgroup видно, що ці виклики read() відносяться до файлу memory.stat, який показує використання пам'яті та обмеження cgroup (технологія ізоляції ресурсів у Docker). Інструмент cadvisor опитує цей файл, щоб отримати інформацію про використання ресурсів для контейнерів. Давайте перевіримо, це ядро або cadvisor робить щось несподіване:
theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null
real 0m0.153s
user 0m0.000s
sys 0m0.152s
theojulienne@kube-node-bad ~ $
Тепер ми можемо відтворити баг та розуміємо, що ядро Linux стикається з патологією.
Чому операція читання настільки повільна?
На цьому етапі набагато простіше знайти повідомлення інших користувачів про подібні проблеми. Як виявилося, у трекері cadvisor про цей баг повідомляли як про , просто ніхто не помітив, що затримка також випадково відображається в мережевому стеку. Дійсно було помічено, що cadvisor споживає більше процесорного часу, ніж очікувалося, але цьому не надали особливого значення, адже наші сервери мають багато процесорних ресурсів, тому проблему ретельно не вивчали.
Проблема у тому, що контрольні групи (cgroups) враховують використання пам'яті всередині простору імен (контейнера). Коли всі процеси цієї cgroup завершуються, Docker звільняє контрольну групу пам'яті. Однак «пам'ять» – це не просто пам'ять процесу. Хоча сама пам'ять процесів більше не використовується, виявляється, ядро призначає ще кешований вміст, таке як dentries та inodes (метадані каталогів та файлів), які кешуються в memory cgroup. З опису проблеми:
cgroups-зомбі: контрольні групи, в яких немає процесів і вони видалені, але для яких все ще виділена пам'ять (у моєму випадку з кешу dentry, але вона також може виділятися з кешу сторінок або tmpfs).
Перевірка ядром всіх сторінок у кеші при звільненні cgroup може бути дуже повільною, тому вибраний лінивий процес: почекати, поки ці сторінки будуть знову запрошені, і вже тоді, коли пам'ять дійсно знадобиться, нарешті, очистити cgroup. До цього моменту cgroup, як і раніше, враховується при зборі статистики.
З погляду продуктивності, вони пожертвували пам'яттю заради продуктивності: прискорення початкового очищення рахунок того, що залишається трохи кешованої пам'яті. Це нормально. Коли ядро використовує останню частину кешованої пам'яті, cgroup зрештою очищається, тому це не можна назвати «витіком». На жаль, конкретна реалізація механізму пошуку memory.stat у цій версії ядра (4.9), у поєднанні з величезним обсягом пам'яті на наших серверах, призводить до того, що для відновлення останніх кешованих даних та очищення cgroup-зомбі потрібно набагато більше часу.
Виявляється, на деяких наших вузлах було так багато cgroup-зомбі, що читання та затримка перевищували секунду.
Спосіб обходу проблеми cadvisor - негайно звільнити кеші dentries/inodes по всій системі, що відразу усуває затримку читання, а також мережну затримку на хості, оскільки видалення кешу включає кешовані сторінки cgroup-зомбі, а вони також звільняються. Не рішення, але підтверджує причину проблеми.
Виявилося, що в нових версіях ядра (4.19+) покращено продуктивність виклику memory.stat, отже перехід цього ядро усував проблему. У той же час у нас був інструментарій для виявлення проблемних вузлів у кластерах Kubernetes, їхнього витонченого зливу та перезавантаження. Ми прочухали всі кластери, знайшли вузли з досить високою затримкою та перезавантажили їх. Це дало нам час оновлення ОС інших серверах.
Підводячи підсумок
Оскільки цей баг зупиняв обробку черг NIC RX на сотні мілісекунд, він одночасно викликав і велику затримку на коротких з'єднаннях, і затримку в середині з'єднання, наприклад, між запитами MySQL і пакетами у відповідь.
Розуміння та підтримка продуктивності фундаментальних систем, таких як Kubernetes, має вирішальне значення для надійності та швидкості всіх сервісів на їх основі. Від поліпшень продуктивності Kubernetes виграють усі системи, що запускаються.
Джерело: habr.com