Pár éve Kubernetes a hivatalos GitHub blogon. Azóta a szolgáltatások bevezetésének standard technológiája lett. A Kubernetes jelenleg a belső és közszolgáltatások jelentős részét kezeli. Ahogy fürtjeink nőttek, és a teljesítménykövetelmények egyre szigorúbbá váltak, azt vettük észre, hogy a Kubernetes egyes szolgáltatásai szórványosan késleltetést tapasztalnak, ami nem magyarázható magának az alkalmazásnak a terhelésével.
Lényegében az alkalmazások látszólag véletlenszerű hálózati késleltetést tapasztalnak akár 100 ms-ig vagy annál hosszabb ideig, ami időtúllépéseket vagy újrapróbálkozásokat eredményez. A szolgáltatások várhatóan 100 ms-nál sokkal gyorsabban tudnak válaszolni a kérésekre. De ez lehetetlen, ha maga a kapcsolat ilyen sok időt vesz igénybe. Külön-külön is megfigyeltük a nagyon gyors MySQL-lekérdezéseket, amelyeknek ezredmásodperceket kell igénybe venniük, és a MySQL ezredmásodperc alatt fejeződött be, de a kérelmező alkalmazás szempontjából a válasz 100 ms-ig vagy tovább tartott.
Azonnal világossá vált, hogy a probléma csak Kubernetes csomóponthoz való csatlakozáskor jelentkezett, még akkor is, ha a hívás Kubernetesen kívülről érkezett. A probléma reprodukálásának legegyszerűbb módja egy teszt , amely bármely belső gazdagépről fut, egy adott porton teszteli a Kubernetes szolgáltatást, és szórványosan magas késleltetést regisztrál. Ebben a cikkben megvizsgáljuk, hogyan tudtuk felderíteni a probléma okát.
A meghibásodáshoz vezető lánc szükségtelen bonyolultságának kiküszöbölése
Ugyanennek a példának a reprodukálásával a probléma fókuszát szűkíteni akartuk, és eltávolítottuk a szükségtelen összetettségi rétegeket. Kezdetben túl sok elem volt a Vegeta és a Kubernetes hüvelyek közötti áramlásban. Egy mélyebb hálózati probléma azonosításához ki kell zárnia néhányat.
A kliens (Vegeta) TCP kapcsolatot hoz létre a fürt bármely csomópontjával. A Kubernetes overlay hálózatként működik (a meglévő adatközponti hálózaton felül), amely használja , azaz az átfedő hálózat IP-csomagjait az adatközpont IP-csomagjaiba zárja be. Az első csomóponthoz való csatlakozáskor hálózati cím fordítás történik (NAT) állapottartó a Kubernetes-csomópont IP-címének és portjának lefordítása az átfedő hálózat IP-címére és portjára (pontosabban az alkalmazást tartalmazó pod). A bejövő csomagok esetében a műveletek fordított sorrendje kerül végrehajtásra. Ez egy összetett rendszer, sok állapottal és sok elemmel, amelyek folyamatosan frissülnek és változnak a szolgáltatások telepítése és áthelyezése során.
Hasznosság tcpdump a Vegeta tesztben késés van a TCP kézfogás során (a SYN és a SYN-ACK között). A szükségtelen bonyolultság eltávolításához használhatja hping3 egyszerű „ping”-ekhez SYN-csomagokkal. Ellenőrizzük, hogy van-e késés a válaszcsomagban, majd visszaállítjuk a kapcsolatot. Szűrhetjük az adatokat úgy, hogy csak a 100 ms-nál nagyobb csomagokat tartalmazzák, és könnyebben reprodukálhatjuk a problémát, mint a Vegeta teljes hálózati 7. rétegű tesztje. Itt vannak a Kubernetes-csomópont "pingek" a TCP SYN/SYN-ACK használatával a szolgáltatás "csomópont-portján" (30927) 10 ms-os időközönként, a leglassabb válaszok alapján szűrve:
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
Azonnal megteheti az első megfigyelést. A sorszámokból és az időzítésekből ítélve egyértelmű, hogy nem egyszeri torlódásokról van szó. A késleltetés gyakran felhalmozódik, és végül feldolgozzák.
Ezt követően azt szeretnénk kideríteni, hogy mely összetevők lehetnek köze a torlódások előfordulásához. Talán ez néhány a NAT több száz iptables szabálya közül? Vagy van valami probléma az IPIP alagúttal a hálózaton? Ennek tesztelésének egyik módja az, hogy a rendszer minden egyes lépését kiiktatva teszteljük. Mi történik, ha eltávolítja a NAT-ot és a tűzfallogikát, és csak az IPIP részt hagyja meg:
Szerencsére a Linux megkönnyíti az IP overlay réteg közvetlen elérését, ha a gép ugyanazon a hálózaton van:
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
Az eredményekből ítélve a probléma továbbra is fennáll! Ez nem tartalmazza az iptables-t és a NAT-ot. Tehát a probléma a TCP-vel van? Nézzük meg, hogyan megy egy normál ICMP ping:
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
Az eredmények azt mutatják, hogy a probléma nem szűnt meg. Talán ez egy IPIP alagút? Egyszerűsítsük tovább a tesztet:
Minden csomag elküldésre kerül e két gazdagép között?
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
Leegyszerűsítettük a helyzetet, hogy két Kubernetes-csomópont küldjön egymásnak bármilyen csomagot, még egy ICMP-pinget is. Még mindig látják a késleltetést, ha a célállomás "rossz" (néhány rosszabb, mint mások).
Most az utolsó kérdés: miért csak a kube-node szervereken jelentkezik a késés? És ez akkor történik, ha a kube-node a küldő vagy a fogadó? Szerencsére ezt is elég könnyű kitalálni, ha küldünk egy csomagot egy Kubernetesen kívüli gazdagépről, de ugyanazzal az „ismert rossz” címzetttel. Mint látható, a probléma nem szűnt meg:
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
Ezután ugyanazokat a kéréseket futtatjuk az előző forrás kube-node-tól a külső gazdagéphez (ami kizárja a forrásgazdagépet, mivel a ping RX és TX összetevőt is tartalmaz):
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
A késleltetésű csomagrögzítések vizsgálatával további információkat kaptunk. Pontosabban, hogy a feladó (alul) látja ezt az időtúllépést, de a címzett (fent) nem – lásd a Delta oszlopot (másodpercben):
Ráadásul, ha megnézzük a címzett oldalon a TCP és ICMP csomagok sorrendjének különbségét (sorszámok szerint), akkor az ICMP csomagok mindig ugyanabban a sorrendben érkeznek, amelyben elküldték őket, de eltérő időzítéssel. Ugyanakkor a TCP-csomagok időnként átlapolódnak, és néhányuk elakad. Különösen, ha megvizsgáljuk a SYN csomagok portjait, akkor azok a küldő oldalon rendben vannak, a fogadó oldalon viszont nem.
Van egy apró különbség a hogyanban a modern szerverek (mint az adatközpontunkban lévők) TCP-t vagy ICMP-t tartalmazó csomagokat dolgoznak fel. Amikor megérkezik egy csomag, a hálózati adapter "kapcsolatonként kivonatolja", vagyis megpróbálja sorokra bontani a kapcsolatokat, és minden sort egy külön processzormagba küldeni. TCP esetén ez a hash tartalmazza a forrás és a cél IP-címét és portját is. Más szavakkal, minden kapcsolat másként (potenciálisan) kivonatolt. Az ICMP esetében csak az IP-címek kivonatolása történik, mivel nincsenek portok.
Egy másik új megfigyelés: ebben az időszakban ICMP késéseket látunk a két gazdagép közötti összes kommunikációban, de a TCP nem. Ez azt mutatja, hogy az ok valószínűleg az RX-sor kivonatával kapcsolatos: a torlódás szinte biztosan az RX-csomagok feldolgozásában van, nem pedig a válaszok küldésében.
Ez kiküszöböli a csomagok küldését a lehetséges okok listájáról. Ma már tudjuk, hogy a csomagfeldolgozási probléma egyes kube-node szervereken a fogadási oldalon van.
A csomagfeldolgozás megértése a Linux kernelben
Hogy megértsük, miért fordul elő a probléma a vevőnél néhány kube-csomópont-kiszolgálón, nézzük meg, hogyan dolgozza fel a Linux kernel a csomagokat.
Visszatérve a legegyszerűbb hagyományos megvalósításhoz, a hálózati kártya fogadja a csomagot és elküldi a Linux kernel, hogy van egy csomag, amit fel kell dolgozni. A kernel leállítja a többi munkát, átkapcsolja a környezetet a megszakításkezelőre, feldolgozza a csomagot, majd visszatér az aktuális feladatokhoz.
Ez a kontextusváltás lassú: a késleltetés a 10-es években talán nem volt észrevehető a 90 Mbps-os hálózati kártyákon, de a modern 10G kártyákon, amelyek maximális áteresztőképessége 15 millió csomag/másodperc, egy kis nyolcmagos szerver minden magja milliókat megszakíthat. másodpercenkénti alkalommal.
Annak érdekében, hogy ne kezelje folyamatosan a megszakításokat, sok évvel ezelőtt hozzáadta a Linuxot : Hálózati API, amelyet minden modern illesztőprogram használ a nagy sebességű teljesítmény javítására. Alacsony sebességen a kernel továbbra is a régi módon kap megszakításokat a hálózati kártyáról. Amint elegendő csomag érkezik, amely meghaladja a küszöbértéket, a kernel letiltja a megszakításokat, és ehelyett elkezdi lekérdezni a hálózati adaptert, és a csomagokat darabokra szedni. A feldolgozás softirq-ban, azaz in rendszerhívások és hardveres megszakítások után, amikor a kernel (a felhasználói területtel ellentétben) már fut.
Ez sokkal gyorsabb, de más problémát okoz. Ha túl sok a csomag, akkor minden idő a csomagok hálózati kártyáról történő feldolgozásával telik, és a felhasználói térfolyamatoknak nincs idejük ténylegesen kiüríteni ezeket a sorokat (TCP-kapcsolatok olvasása stb.). Végül a sorok megtelnek, és elkezdjük dobni a csomagokat. Az egyensúly megtalálása érdekében a kernel költségvetést állít be a softirq környezetben feldolgozott csomagok maximális számához. Ha ezt a költségvetést túllépjük, egy külön szál ébred fel ksoftirqd (az egyiket látni fogod ps magonként), amely ezeket a softirq-eket a normál syscall/megszakítási útvonalon kívül kezeli. Ez a szál a szabványos folyamatütemezővel van ütemezve, amely megkísérli az erőforrások igazságos elosztását.
Miután megvizsgálta, hogy a kernel hogyan dolgozza fel a csomagokat, láthatja, hogy van bizonyos valószínűsége a torlódásnak. Ha ritkábban érkezik softirq hívás, akkor a csomagoknak várniuk kell egy ideig a hálózati kártya RX sorban lévő feldolgozásáig. Ennek oka lehet, hogy valamilyen feladat blokkolja a processzormagot, vagy valami más akadályozza meg a mag softirq futtatását.
A feldolgozás leszűkítése a magra vagy módszerre
A Softirq késések egyelőre csak találgatások. De van értelme, és tudjuk, hogy valami nagyon hasonlót látunk. A következő lépés tehát ennek az elméletnek a megerősítése. És ha beigazolódik, akkor keresse meg a késések okát.
Térjünk vissza lassú csomagjainkhoz:
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
Amint azt korábban tárgyaltuk, ezek az ICMP-csomagok egyetlen RX NIC-sorba vannak kivonatolva, és egyetlen CPU-mag dolgozza fel. Ha meg akarjuk érteni a Linux működését, hasznos tudni, hogy hol (melyik CPU-magon) és hogyan (softirq, ksoftirqd) dolgozzák fel ezeket a csomagokat a folyamat nyomon követése érdekében.
Itt az ideje, hogy olyan eszközöket használjunk, amelyek lehetővé teszik a Linux kernel valós idejű figyelését. Itt használtuk . Ez az eszközkészlet lehetővé teszi olyan kis C-programok írását, amelyek tetszőleges függvényeket kapcsolnak be a kernelbe, és pufferolják az eseményeket egy felhasználói területű Python programba, amely feldolgozza azokat, és visszaküldi az eredményt. A kernelbe tetszőleges függvények beiktatása trükkös dolog, de a segédprogramot a maximális biztonságra tervezték, és arra tervezték, hogy pontosan olyan gyártási problémákat keressen, amelyek teszt- vagy fejlesztői környezetben nem könnyen reprodukálhatók.
A terv itt egyszerű: tudjuk, hogy a kernel feldolgozza ezeket az ICMP-pingeket, ezért a kernel függvényét akasztóval látjuk el. , amely elfogad egy bejövő ICMP visszhang kérés csomagot, és kezdeményezi az ICMP visszhang válasz küldését. Egy csomagot az icmp_seq szám növelésével azonosíthatunk, ami megmutatja hping3 magasabb.
Kód bonyolultnak tűnik, de nem olyan ijesztő, mint amilyennek látszik. Funkció icmp_echo továbbítja struct sk_buff *skb: Ez egy "visszhang kéréssel" rendelkező csomag. Követhetjük, kihúzhatjuk a sorozatot echo.sequence (amihez képest icmp_seq szerző: hping3 выше), és küldje el a felhasználói térbe. Kényelmes az aktuális folyamatnév/azonosító rögzítése is. Alább láthatók azok az eredmények, amelyeket közvetlenül látunk, miközben a kernel csomagokat dolgoz fel:
TGID PID FOLYAMAT NÉV ICMP_SEQ 0 0 csere/11 770 0 csere/0 11 771 csere/0 0 11 csere/772 0 0 cserélő/11 773 0 prométheusz 0 11 774 csere/20041 20086 775 csere/0 0 11 csere/776 0 0 szóvivői jelentés 11
Itt kell megjegyezni, hogy az összefüggésben softirq A rendszerhívásokat végző folyamatok „folyamatokként” jelennek meg, holott valójában a kernel az, amely biztonságosan dolgozza fel a csomagokat a kernel kontextusában.
Ezzel az eszközzel bizonyos folyamatokat társíthatunk meghatározott csomagokhoz, amelyek késleltetést mutatnak hping3. Tegyük egyszerűvé grep ezen a rögzítésén bizonyos értékekre icmp_seq. A fenti icmp_seq értékeknek megfelelő csomagokat a fent megfigyelt RTT-vel együtt megjelöltük (zárójelben az 50 ms-nál kisebb RTT-értékek miatt kiszűrt csomagok várható RTT értékei):
TGID PID FOLYAMAT NÉV ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 ** 1953ms 99 76 ksoftirqd/76 11 ** 1954ms 89 76 ksoftirqd/76 11 ** 1955ms 79 76 ksoftirqd/76 11 ** 1956ms 69 76 ksoftirqd/76 ** 11ms 1957 59 ksoftirqd/76 76 ** (11ms) 1958 49 ksoftirqd/76. 76. ** (11 ms) 1959 39 ksoftirqd/76 76** (11ms) 1960 29 ksoftirqd/76 76 ** (11ms) 1961 19 ksoftirqd/76 76 ** (11ms) -- 1962 9 cadvisor 10137 10436 2068 cadvisor 10137 10436 2069 ksoftirqd/76 76 ** 11ms 2070 75 ksoftirqd/76 76 ** 11ms 2071 65 ksoftirqd/76 76 ** 11ms 2072 55 ksoftirqd/76 76 ** (11 ms) 2073 45 ksoftirqd/76 76 ** (11 ms) 2074 35 ksoftirqd/76 76 ** (11 ms) 2075 25 ksoftirqd/76 76 ** (11 ms) 2076 15 ksoftirqd/76 76 ** (11 ms)
Az eredmények több dolgot is elárulnak. Először is, ezeket a csomagokat a környezet dolgozza fel ksoftirqd/11. Ez azt jelenti, hogy ennél a géppárnál az ICMP-csomagok kivonatolásra kerültek a 11. maghoz a fogadó oldalon. Azt is látjuk, hogy amikor elakadás van, vannak csomagok, amelyeket a rendszerhívás keretében dolgoznak fel cadvisor... Akkor ksoftirqd átveszi a feladatot, és feldolgozza a felhalmozott sort: pontosan annyi csomagot, amennyi után felhalmozódott cadvisor.
Az a tény, hogy közvetlenül előtte mindig működik cadvisor, azt jelenti, hogy részt vesz a problémában. Ironikus módon a cél - "elemezze a futó tárolók erőforráshasználatát és teljesítményjellemzőit" ahelyett, hogy ezt a teljesítményproblémát okozná.
A konténerek egyéb vonatkozásaihoz hasonlóan ezek is rendkívül fejlett eszközök, és várhatóan teljesítményproblémákat tapasztalhatnak bizonyos előre nem látható körülmények között.
Mit csinál a cadvisor, ami lelassítja a csomagsort?
Most már elég jól megértjük, hogyan történik az összeomlás, milyen folyamat okozza, és melyik CPU-n. Látjuk, hogy a kemény blokkolás miatt a Linux kernelnek nincs ideje ütemezni ksoftirqd. És azt látjuk, hogy a csomagok feldolgozása kontextusban történik cadvisor. Logikus ezt feltételezni cadvisor lassú rendszerhívást indít, amely után az összes akkor felhalmozott csomag feldolgozásra kerül:
Ez egy elmélet, de hogyan lehet tesztelni? Amit tehetünk, hogy nyomon követjük a CPU magot a folyamat során, megtaláljuk azt a pontot, ahol a csomagok száma meghaladja a költségvetést, és a ksoftirqd meghívásra kerül, majd kicsit távolabbra nézünk, hogy meglássuk, mi futott pontosan a CPU magon közvetlenül azelőtt. . Ez olyan, mintha néhány ezredmásodpercenként röntgenezné a CPU-t. Valahogy így fog kinézni:
Mindez kényelmesen megtehető a meglévő eszközökkel. Például, meghatározott gyakorisággal ellenőrzi az adott CPU magot, és létrehozhat egy ütemezést a futó rendszerhez, beleértve a felhasználói területet és a Linux kernelt is. Ezt a rekordot a program egy kis villájával feldolgozhatja Brendan Greggtől, ami megőrzi a verem nyomának sorrendjét. 1 ms-onként menthetjük az egysoros veremnyomokat, majd kiemelhetünk és menthetünk egy mintát 100 ezredmásodperccel a nyomkövetés elérése előtt 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
Íme az eredmények:
(сотни следов, которые выглядят похожими)
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
Sok minden van itt, de a lényeg az, hogy megtaláljuk a „cadvisor before ksoftirqd” mintát, amit korábban láttunk az ICMP nyomkövetőben. Mit jelent?
Minden sor egy CPU nyomkövetés egy adott időpontban. A sorban minden egyes hívást pontosvessző választ el. A sorok közepén látjuk, hogy a syscall neve: read(): .... ;do_syscall_64;sys_read; .... Tehát a cadvisor sok időt tölt a rendszerhívással read()funkciókkal kapcsolatos mem_cgroup_* (a hívási verem teteje/sor vége).
Kényelmetlen látni a hívásnyomban, hogy pontosan mit olvasunk, ezért futtassuk strace és nézzük meg, mit csinál a cadvisor, és keressük meg a 100 ms-nál hosszabb rendszerhívásokat:
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>
Ahogy az várható volt, itt lassú hívásokat látunk read(). Az olvasási műveletek és a kontextus tartalmából mem_cgroup egyértelmű, hogy ezek a kihívások read() hivatkozzon a fájlra memory.stat, amely a memóriahasználatot és a cgroup korlátokat mutatja (Docker erőforrás-izolációs technológiája). A cadvisor eszköz lekérdezi ezt a fájlt, hogy megkapja a tárolók erőforráshasználati adatait. Ellenőrizzük, hogy a kernel vagy a cadvisor nem csinál-e váratlant:
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 ~ $
Most reprodukálhatjuk a hibát, és megérthetjük, hogy a Linux kernel patológiával néz szembe.
Miért olyan lassú az olvasási művelet?
Ebben a szakaszban sokkal könnyebb megtalálni a többi felhasználó hasonló problémákkal kapcsolatos üzeneteit. Mint kiderült, a cadvisor trackerben ezt a hibát a következő néven jelentették , csak senki nem vette észre, hogy a késleltetés véletlenszerűen tükröződik a hálózati veremben is. Valóban feltűnt, hogy a cadvisor a vártnál több CPU-időt fogyaszt, de ennek nem tulajdonítottak nagy jelentőséget, mivel szervereink sok CPU erőforrással rendelkeznek, így a problémát nem vizsgálták meg alaposan.
A probléma az, hogy a cgroupok figyelembe veszik a névtéren (tárolón) belüli memóriahasználatot. Amikor a cgroup összes folyamata kilép, a Docker felszabadítja a memória-ccsoportot. A „memória” azonban nem csak folyamatmemória. Bár magát a folyamatmemóriát már nem használják, úgy tűnik, hogy a kernel továbbra is gyorsítótárazott tartalmakat rendel hozzá, például dentriákat és inode-okat (könyvtár- és fájlmetaadatok), amelyek a memória cgroupban vannak gyorsítótárazva. A probléma leírásából:
zombi cgroups: olyan cgroupok, amelyeknek nincs folyamata és törölve lettek, de még van memória lefoglalva (esetemben a dentry cache-ből, de az oldal gyorsítótárából vagy tmpfs-ből is lefoglalható).
A gyorsítótárban lévő összes oldal kernel általi ellenőrzése a cgroup felszabadításakor nagyon lassú lehet, ezért a lusta folyamatot választjuk: várja meg, amíg újra lekérik ezeket az oldalakat, majd végül törölje ki a cgroupot, amikor valóban szükség van a memóriára. Eddig a pontig a cgroup-ot továbbra is figyelembe veszik a statisztikák gyűjtésénél.
A teljesítmény szempontjából feláldozták a memóriát a teljesítményért: felgyorsították a kezdeti tisztítást azáltal, hogy néhány gyorsítótárazott memóriát hátrahagytak. Ez jó. Amikor a kernel az utolsó gyorsítótárazott memóriát használja, a cgroup végül törlődik, így nem nevezhető "szivárgásnak". Sajnos a keresési mechanizmus konkrét végrehajtása memory.stat Ebben a kernelverzióban (4.9), a szervereink hatalmas memóriájával együtt azt jelenti, hogy sokkal tovább tart a legfrissebb gyorsítótárazott adatok visszaállítása és a cgroup zombik törlése.
Kiderült, hogy néhány csomópontunkban annyi cgroup zombi volt, hogy az olvasási és késleltetési idő meghaladta a másodpercet.
A cadvisor probléma megoldása az, hogy azonnal fel kell szabadítani a dentries/inodes gyorsítótárakat a rendszerben, ami azonnal kiküszöböli az olvasási késleltetést, valamint a hálózati késleltetést a gazdagépen, mivel a gyorsítótár törlése bekapcsolja a gyorsítótárazott cgroup zombi oldalakat, és felszabadítja azokat is. Ez nem megoldás, de megerősíti a probléma okát.
Kiderült, hogy az újabb kernelverziókban (4.19+) javult a hívási teljesítmény memory.stat, így az erre a kernelre váltás megoldotta a problémát. Ugyanakkor eszközeink voltak a Kubernetes-fürtök problémás csomópontjainak észlelésére, kecses leürítésére és újraindítására. Átfésültük az összes klasztert, találtunk elég magas késleltetésű csomópontokat, és újraindítottuk őket. Így volt időnk frissíteni az operációs rendszert a többi szerveren.
Összefoglalva
Mivel ez a hiba több száz ezredmásodpercre leállította az RX hálózati kártyák sorfeldolgozását, egyszerre okozott magas késleltetést a rövid kapcsolatoknál és közepes csatlakozási késést, például a MySQL-kérelmek és a válaszcsomagok között.
A legalapvetőbb rendszerek – például a Kubernetes – megértése és teljesítményének fenntartása kritikus fontosságú az ezeken alapuló összes szolgáltatás megbízhatósága és sebessége szempontjából. Minden futtatott rendszer részesül a Kubernetes teljesítménybeli fejlesztéseiben.
Forrás: will.com