Antaŭ kelkaj jaroj Kubernetes en la oficiala GitHub-blogo. Ekde tiam, ĝi fariĝis la norma teknologio por disfaldi servojn. Kubernetes nun administras signifan parton de internaj kaj publikaj servoj. Ĉar niaj aretoj kreskis kaj agado postuloj fariĝis pli striktaj, ni komencis rimarki, ke iuj servoj en Kubernetes sporade spertis latentecon, kiu ne povus esti klarigita per la ŝarĝo de la aplikaĵo mem.
Esence, aplikoj spertas hazardan retan latentecon de ĝis 100ms aŭ pli, rezultigante tempodaŭrojn aŭ reprovojn. Servoj estis atenditaj povi respondi al petoj multe pli rapide ol 100ms. Sed ĉi tio estas neebla se la konekto mem prenas tiom da tempo. Aparte, ni observis tre rapidajn MySQL-demandojn, kiuj devus preni milisekundojn, kaj MySQL plenumis en milisekundoj, sed el la perspektivo de la petanta aplikaĵo, la respondo daŭris 100 ms aŭ pli.
Tuj evidentiĝis, ke la problemo okazis nur kiam oni konektis al Kubernetes-nodo, eĉ se la voko venis de ekster Kubernetes. La plej facila maniero reprodukti la problemon estas en testo , kiu kuras de iu ajn interna gastiganto, testas la Kubernetes-servon sur specifa haveno, kaj sporade registras altan latentecon. En ĉi tiu artikolo, ni rigardos kiel ni povis spuri la kaŭzon de ĉi tiu problemo.
Forigante nenecesan kompleksecon en la ĉeno kondukanta al fiasko
Reproduktante la saman ekzemplon, ni volis malvastigi la fokuson de la problemo kaj forigi nenecesajn tavolojn de komplekseco. Komence, estis tro da elementoj en la fluo inter Vegeta kaj la Kubernetes balgoj. Por identigi pli profundan retan problemon, vi devas forĵeti kelkajn el ili.
La kliento (Vegeta) kreas TCP-konekton kun iu ajn nodo en la areto. Kubernetes funkcias kiel superkovra reto (aldone al la ekzistanta datumcentra reto) kiu uzas , tio estas, ĝi enkapsuligas la IP-pakojn de la superkovra reto ene de la IP-pakoj de la datumcentro. Konektante al la unua nodo, tradukado de retadresoj estas farita (NAT) stateful traduki la IP-adreson kaj havenon de la Kubernetes-nodo al la IP-adreso kaj haveno en la superkovra reto (specife, la pod kun la aplikaĵo). Por envenantaj pakaĵetoj, la inversa sekvenco de agoj estas farita. Ĝi estas kompleksa sistemo kun multe da stato kaj multaj elementoj, kiuj estas konstante ĝisdatigitaj kaj ŝanĝitaj dum servoj estas deplojitaj kaj movitaj.
Utileco tcpdump en la testo Vegeta estas prokrasto dum la TCP-manpremo (inter SYN kaj SYN-ACK). Por forigi ĉi tiun nenecesan kompleksecon, vi povas uzi hping3 por simplaj "pingoj" kun SYN-pakoj. Ni kontrolas ĉu estas malfruo en la responda pako, kaj poste restarigas la konekton. Ni povas filtri la datumojn por inkluzivi nur pakaĵojn pli grandajn ol 100ms kaj akiri pli facilan manieron reprodukti la problemon ol la plena reto-tavolo 7-testo de Vegeta. Jen Kubernetes-nodo "pingoj" uzante TCP SYN/SYN-ACK sur la servo "noda haveno" (30927) je 10ms intervaloj, filtritaj per plej malrapidaj respondoj:
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
Povas tuj fari la unuan observon. Juĝante laŭ la sinsekvaj nombroj kaj tempoj, estas klare, ke ĉi tiuj ne estas unufojaj ŝtopiĝo. La prokrasto ofte akumuliĝas kaj estas poste prilaborita.
Poste, ni volas ekscii, kiuj komponantoj povas esti implikitaj en la okazo de kongesto. Eble ĉi tiuj estas kelkaj el la centoj da iptablej reguloj en NAT? Aŭ ĉu ekzistas problemoj pri IPIP-tunado en la reto? Unu maniero por kontroli ĉi tion estas testi ĉiun paŝon de la sistemo forigante ĝin. Kio okazas se vi forigas NAT kaj fajroŝirmilon, lasante nur la IPIP-parton:
Feliĉe, Linukso faciligas rekte aliri la IP-kovrantan tavolon se la maŝino estas en la sama reto:
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
Juĝante laŭ la rezultoj, la problemo ankoraŭ restas! Ĉi tio ekskludas iptables kaj NAT. Do la problemo estas TCP? Ni vidu kiel regula ICMP-pingo iras:
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
La rezultoj montras, ke la problemo ne malaperis. Eble ĉi tio estas IPIP-tunelo? Ni simpligu la teston plu:
Ĉu ĉiuj pakoj estas senditaj inter ĉi tiuj du gastigantoj?
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
Ni simpligis la situacion al du Kubernetes-nodoj sendantaj unu la alian ajnan pakaĵon, eĉ ICMP-pingon. Ili ankoraŭ vidas latentecon se la cela gastiganto estas "malbona" (iuj pli malbonaj ol aliaj).
Nun la lasta demando: kial la prokrasto okazas nur ĉe kube-nodaj serviloj? Kaj ĉu okazas kiam kube-node estas la sendinto aŭ la ricevilo? Feliĉe, ĉi tio ankaŭ estas sufiĉe facile eltrovebla sendante paketon de gastiganto ekster Kubernetes, sed kun la sama "konata malbona" ricevanto. Kiel vi povas vidi, la problemo ne malaperis:
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
Ni tiam rulos la samajn petojn de la antaŭa fonta kube-nodo al la ekstera gastiganto (kiu ekskludas la fontan gastiganton ĉar la ping inkluzivas ambaŭ komponanton RX kaj 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
Ekzamenante latenciajn pakaĵetojn, ni akiris kelkajn pliajn informojn. Specife, ke la sendinto (malsupre) vidas ĉi tiun tempon, sed la ricevanto (supro) ne - vidas la Delta-kolumnon (en sekundoj):
Krome, se vi rigardas la diferencon en la ordo de TCP kaj ICMP-pakaĵetoj (laŭ sinsekvaj nombroj) ĉe la ricevanto, ICMP-pakoj ĉiam alvenas en la sama sinsekvo en kiu ili estis senditaj, sed kun malsama tempo. Samtempe, TCP-pakoj foje interplekiĝas, kaj kelkaj el ili blokiĝas. Aparte, se vi ekzamenas la havenojn de SYN-pakoj, ili estas en ordo flanke de la sendinto, sed ne flanke de la ricevilo.
Estas subtila diferenco en kiel modernaj serviloj (kiel tiuj en nia datumcentro) prilaboras pakaĵetojn enhavantajn TCP aŭ ICMP. Kiam pakaĵeto alvenas, la retadaptilo "haŝas ĝin per konekto", tio estas, ĝi provas rompi la konektojn en vostojn kaj sendi ĉiun atendovicon al aparta procesorokerno. Por TCP, ĉi tiu hash inkluzivas kaj la fonton kaj celon IP-adreson kaj havenon. Alivorte, ĉiu konekto estas haŝita (eble) alimaniere. Por ICMP, nur IP-adresoj estas haŝita, ĉar ekzistas neniuj havenoj.
Alia nova observo: dum ĉi tiu periodo ni vidas ICMP-prokrastojn pri ĉiuj komunikadoj inter du gastigantoj, sed TCP ne. Ĉi tio diras al ni, ke la kaŭzo verŝajne rilatas al RX-vostohakado: la obstrukciĝo preskaŭ certe estas en la prilaborado de RX-pakoj, ne en la sendo de respondoj.
Ĉi tio forigas sendi pakaĵojn el la listo de eblaj kaŭzoj. Ni nun scias, ke la problemo pri paka pretigo estas ĉe la riceva flanko ĉe iuj kube-nodaj serviloj.
Komprenante pakaĵan prilaboradon en la Linukso-kerno
Por kompreni kial la problemo okazas ĉe la ricevilo sur kelkaj kube-nodaj serviloj, ni rigardu kiel la Linukso-kerno prilaboras pakaĵojn.
Revenante al la plej simpla tradicia efektivigo, la retkarto ricevas la pakaĵon kaj sendas la Linukso-kerno, ke ekzistas pakaĵo, kiu devas esti prilaborita. La kerno ĉesigas alian laboron, ŝanĝas kuntekston al la interrompa prizorganto, prilaboras la pakaĵeton, kaj poste revenas al la nunaj taskoj.
Ĉi tiu kuntekstoŝanĝo estas malrapida: latencia eble ne estis rimarkebla sur 10Mbps retkartoj en la 90-aj jaroj, sed sur modernaj 10G-kartoj kun maksimuma trairo de 15 milionoj da pakaĵetoj sekundo, ĉiu kerno de malgranda ok-kerna servilo povas esti interrompita milionoj. de tempoj por sekundo.
Por ne konstante trakti interrompojn, antaŭ multaj jaroj Linukso aldonis : Reta API, kiun ĉiuj modernaj ŝoforoj uzas por plibonigi rendimenton ĉe altaj rapidecoj. Je malaltaj rapidoj la kerno ankoraŭ ricevas interrompojn de la retkarto laŭ la malnova maniero. Post kiam sufiĉe da pakaĵetoj alvenas kiuj superas la sojlon, la kerno malŝaltas interrompojn kaj anstataŭe komencas baloti la retadaptilon kaj preni pakaĵetojn en pecoj. Pretigo estas farita en softirq, tio estas, en post sistemvokoj kaj aparataj interrompoj, kiam la kerno (kontraste al uzantspaco) jam funkcias.
Ĉi tio estas multe pli rapida, sed kaŭzas malsaman problemon. Se estas tro da pakaĵoj, tiam la tuta tempo estas pasigita por prilabori pakaĵetojn de la retkarto, kaj uzantspacaj procezoj ne havas tempon por efektive malplenigi ĉi tiujn vicojn (legante el TCP-konektoj ktp.). Fine la vicoj pleniĝas kaj ni komencas faligi pakaĵetojn. En provo trovi ekvilibron, la kerno fiksas buĝeton por la maksimuma nombro da pakaĵetoj prilaboritaj en la softirq-kunteksto. Post kiam ĉi tiu buĝeto estas superita, aparta fadeno estas vekita ksoftirqd (vi vidos unu el ili en ps per kerno) kiu pritraktas tiujn softirqs ekster la normala syscall/interrompa vojo. Ĉi tiu fadeno estas planita uzante la norman procezplanilon, kiu provas asigni rimedojn juste.
Studinte kiel la kerno prilaboras pakaĵojn, vi povas vidi, ke ekzistas certa verŝajneco de kongesto. Se softirq-vokoj estas ricevitaj malpli ofte, pakaĵoj devos atendi iom da tempo por esti procesitaj en la RX-vico sur la retkarto. Ĉi tio povas esti pro iu tasko blokanta la procesoran kernon, aŭ io alia malhelpas la kernon ruli softirq.
Malvastigante la prilaboradon al la kerno aŭ metodo
Softirq-prokrastoj estas nur supozo nuntempe. Sed ĝi havas sencon, kaj ni scias, ke ni vidas ion tre similan. Do la sekva paŝo estas konfirmi ĉi tiun teorion. Kaj se ĝi estas konfirmita, tiam trovu la kialon de la malfruoj.
Ni revenu al niaj malrapidaj pakoj:
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
Kiel diskutite antaŭe, ĉi tiuj ICMP-pakoj estas hakitaj en ununuran RX NIC-vicon kaj prilaboritaj per ununura CPU-kerno. Se ni volas kompreni kiel funkcias Linukso, estas utile scii kie (sur kiu CPU-kerno) kaj kiel (softirq, ksoftirqd) ĉi tiuj pakaĵoj estas prilaboritaj por spuri la procezon.
Nun estas tempo uzi ilojn, kiuj permesas vin kontroli la Linuksan kernon en reala tempo. Ĉi tie ni uzis . Ĉi tiu aro de iloj permesas vin skribi malgrandajn C-programojn, kiuj enganĉas arbitrajn funkciojn en la kerno kaj bufras la eventojn en uzantspacan Python-programon, kiu povas prilabori ilin kaj redoni la rezulton al vi. Hoki arbitrajn funkciojn en la kerno estas kompleksa afero, sed la utileco estas desegnita por maksimuma sekureco kaj estas dizajnita por spuri precize la specon de produktadaj aferoj kiuj ne estas facile reproduktitaj en testa aŭ evolumedio.
La plano ĉi tie estas simpla: ni scias, ke la kerno prilaboras ĉi tiujn ICMP-pingojn, do ni metos hokon sur la kernan funkcion. , kiu akceptas alvenantan ICMP-eĥopetpakaĵon kaj iniciatas sendi ICMP-eĥrespondon. Ni povas identigi pakaĵon pliigante la icmp_seq nombron, kiu montras hping3 pli alta.
Kodo aspektas komplika, sed ĝi ne estas tiel timiga kiel ŝajnas. Funkcio icmp_echo transdonas struct sk_buff *skb: Ĉi tio estas pako kun "eĥopeto". Ni povas spuri ĝin, eltiri la sekvencon echo.sequence (kiu komparas kun icmp_seq de hping3 выше), kaj sendu ĝin al uzantspaco. Estas ankaŭ oportune kapti la nunan proceznomon/id. Malsupre estas la rezultoj, kiujn ni vidas rekte dum la kerno prilaboras pakaĵojn:
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 swapper/prometeo/swapper/775 0 0 11 776 swapper/0 0 11 777 0 0 interŝanĝisto/11 778 4512 4542 spokoj-raporto-s 779
Oni notu ĉi tie, ke en la kunteksto softirq procezoj kiuj faris sistemvokojn aperos kiel "procezoj" kiam fakte estas la kerno kiu sekure prilaboras pakaĵetojn en la kunteksto de la kerno.
Kun ĉi tiu ilo ni povas asocii specifajn procezojn kun specifaj pakoj, kiuj montras malfruon de hping3. Ni simpligu ĝin grep pri ĉi tiu kapto por certaj valoroj icmp_seq. Pakoj kongruantaj kun la supraj icmp_seq-valoroj estis notitaj kune kun ilia RTT, kiun ni observis supre (en krampoj estas la atendataj RTT-valoroj por pakoj, kiujn ni filtris pro RTT-valoroj malpli ol 50 ms):
TGID PID PROCESA NOMO ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftirqd/11 ** 1954ms 89 76 ksoftir 76 ir qd/11 1955 ** 79ms 76 76 ksoftirqd/ 11 1956 ** 69ms 76 76 ksoftirqd/11 1957 ** 59ms 76 76 ksoftirqd/11 1958 ** (49ms) 76 76 ksoftirqd/11 1959 ** (39ms 76 76 ksoftirqd/11 1960 ** (29ms) 76 76 ksoftirqd/11 1961 ** (19ms 76/76) (11ms 1962) 9 10137 ksoft irqd/ 10436 2068 ** (10137ms) 10436 2069 ksoftirqd/76 76 ** (11ms) -- 2070 75 cadvisor 76 76 11 cadvisor 2071 65 76 ksoftir 76 ksoftir **11 irqd/2072 55 ** 76ms 76 11 ksoftirqd/ 2073 45 ** 76ms 76 11 ksoftirqd/2074 35 ** (76ms) 76 11 ksoftirqd/2075 25 ** (76ms) 76 11 ksoftirqd/2076 15 **76 **76 ** (11 ms ) 2077 5 ksoftirqd/XNUMX XNUMX ** (XNUMXms)
La rezultoj rakontas al ni plurajn aferojn. Unue, ĉiuj ĉi tiuj pakoj estas procesitaj de la kunteksto ksoftirqd/11. Ĉi tio signifas, ke por ĉi tiu aparta paro de maŝinoj, ICMP-pakoj estis hakitaj al kerno 11 ĉe la riceva fino. Ni ankaŭ vidas, ke kiam ajn estas blokiĝo, estas pakaĵoj, kiuj estas procesitaj en la kunteksto de la sistema voko. cadvisor. Tiam ksoftirqd transprenas la taskon kaj prilaboras la amasigitan vicon: ĝuste la nombro da pakaĵetoj, kiu amasiĝis poste cadvisor.
La fakto, ke tuj antaŭ ĝi ĉiam funkcias cadvisor, implicas lian implikiĝon en la problemo. Ironie, la celo - "analizi la uzadon de rimedoj kaj la funkciojn de funkciado de ujoj" prefere ol kaŭzi ĉi tiun rendimentan problemon.
Kiel ĉe aliaj aspektoj de ujoj, ĉi tiuj ĉiuj estas tre altnivelaj iloj kaj oni povas atendi ke ili spertis rendimentajn problemojn sub iuj neantaŭviditaj cirkonstancoj.
Kion faras cadvisor, kiu malrapidigas la pakvicon?
Ni nun havas sufiĉe bonan komprenon pri kiel la kraŝo okazas, kia procezo kaŭzas ĝin kaj sur kiu CPU. Ni vidas, ke pro malfacila blokado, la Linukso-kerno ne havas tempon por plani ksoftirqd. Kaj ni vidas, ke pakoj estas procesitaj en kunteksto cadvisor. Estas logike supozi tion cadvisor lanĉas malrapidan syscall, post kiu ĉiuj pakaĵoj akumulitaj tiutempe estas prilaboritaj:
Ĉi tio estas teorio, sed kiel provi ĝin? Kion ni povas fari estas spuri la CPU-kernon dum ĉi tiu procezo, trovi la punkton kie la nombro da pakaĵoj superas buĝeton kaj ksoftirqd estas nomita, kaj tiam rigardi iom pli malantaŭen por vidi kio ĝuste funkciis sur la CPU-kerno ĵus antaŭ tiu punkto. . Estas kvazaŭ radiografio de la CPU ĉiujn kelkajn milisekundojn. Ĝi aspektos kiel ĉi tio:
Oportune, ĉio ĉi povas esti farita per ekzistantaj iloj. Ekzemple, kontrolas antaŭfiksitan CPU-kernon je specifa frekvenco kaj povas generi horaron de vokoj al la kuranta sistemo, inkluzive de kaj uzantspaco kaj la Linukso-kerno. Vi povas preni ĉi tiun rekordon kaj prilabori ĝin uzante malgrandan forkon de la programo de Brendan Gregg, kiu konservas la ordon de la stakspuro. Ni povas konservi unuliniajn stakspurojn ĉiun 1 ms, kaj poste reliefigi kaj konservi specimenon 100 milisekundojn antaŭ ol la spuro trafos 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
Jen la rezultoj:
(сотни следов, которые выглядят похожими)
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
Estas multaj aferoj ĉi tie, sed la ĉefa afero estas, ke ni trovas la ŝablonon "cadvisor antaŭ ksoftirqd", kiun ni vidis pli frue en la ICMP-spurilo. Kion ĝi signifas?
Ĉiu linio estas CPU-spuro en certa tempo. Ĉiu voko malsupren de la stako sur linio estas apartigita per punktokomo. En la mezo de la linioj ni vidas la syscall nomitan: read(): .... ;do_syscall_64;sys_read; .... Do cadvisor pasigas multe da tempo en la sistema voko read()rilataj al funkcioj mem_cgroup_* (supro de voka stako/fino de linio).
Estas maloportune vidi en vokspuro kio ĝuste estas legata, do ni kuru strace kaj ni vidu kion faras kadvisor kaj trovu sistemajn vokojn pli longajn ol 100 ms:
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>
Kiel vi povus atendi, ni vidas malrapidajn vokojn ĉi tie read(). El la enhavo de legaj operacioj kaj kunteksto mem_cgroup estas klare, ke ĉi tiuj defioj read() raportu al la dosiero memory.stat, kiu montras memoruzadon kaj cgroup-limojn (la rimeda izolita teknologio de Docker). La kadvisor-ilo demandas ĉi tiun dosieron por akiri informojn pri uzado de rimedoj por ujoj. Ni kontrolu ĉu la kerno aŭ kadvisor faras ion neatenditan:
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 ~ $
Nun ni povas reprodukti la cimon kaj kompreni, ke la Linukso-kerno alfrontas patologion.
Kial la legado estas tiel malrapida?
En ĉi tiu etapo, estas multe pli facile trovi mesaĝojn de aliaj uzantoj pri similaj problemoj. Kiel evidentiĝis, en la kadvisor-spurilo ĉi tiu cimo estis raportita kiel , estas nur ke neniu rimarkis ke la latencia ankaŭ estas hazarde reflektita en la reto stako. Oni ja rimarkis, ke cadvisor konsumis pli da CPU-tempo ol atendite, sed ĉi tio ne ricevis multe da graveco, ĉar niaj serviloj havas multajn CPU-rimedojn, do la problemo ne estis zorge studita.
La problemo estas, ke cgroups konsideras memoruzon ene de la nomspaco (ujo). Kiam ĉiuj procezoj en ĉi tiu cgroup eliras, Docker liberigas la memoran cgroup. Tamen, "memoro" ne estas nur procezmemoro. Kvankam la procezmemoro mem ne plu estas uzata, ŝajnas, ke la kerno ankoraŭ asignas kaŝmemorigitajn enhavojn, kiel ekzemple dentriojn kaj inodojn (metadatenoj de dosierujoj kaj dosieroj), kiuj estas konservitaj en la memoro cgroup. El la problemo priskribo:
zombiaj cgroups: cgroups kiuj havas neniujn procezojn kaj estis forigitaj, sed ankoraŭ havas memoron asignita (en mia kazo, el la dentry-kaŝmemoro, sed ĝi ankaŭ povas esti asignita el la paĝa kaŝmemoro aŭ tmpfs).
La kontrolo de la kerno de ĉiuj paĝoj en la kaŝmemoro dum liberigo de cgrupo povas esti tre malrapida, do la maldiligenta procezo estas elektita: atendu ĝis ĉi tiuj paĝoj denove estas petitaj, kaj tiam finfine malplenigu la cgrupon kiam la memoro estas efektive bezonata. Ĝis ĉi tiu punkto, cgroup daŭre estas konsiderata dum kolektado de statistikoj.
De agado, ili oferis memoron por agado: akcelante la komencan purigadon postlasante iom da kaŝmemoro. Ĉi tio estas bone. Kiam la kerno uzas la lastan el la kaŝmemoro, la cgroup estas poste forigita, do ĝi ne povas esti nomita "liko". Bedaŭrinde, la specifa efektivigo de la serĉo mekanismo memory.stat en ĉi tiu kernversio (4.9), kombinita kun la grandega kvanto da memoro sur niaj serviloj, signifas ke necesas multe pli longe restarigi la plej novajn kaŝmemoritajn datumojn kaj purigi cgroup-zombiojn.
Rezultas, ke iuj el niaj nodoj havis tiom da cgroup-zombioj, ke la legado kaj latenco superis sekundon.
La solvo por la cadvisor-problemo estas tuj liberigi dentries/inodes-kaŝmemorojn tra la sistemo, kio tuj forigas legan latentecon same kiel retan latentecon sur la gastiganto, ĉar malplenigi la kaŝmemoron ŝaltas la kaŝmemoritajn zombiajn cgroup-paĝojn kaj liberigas ilin ankaŭ. Ĉi tio ne estas solvo, sed ĝi konfirmas la kaŭzon de la problemo.
Montriĝis, ke en pli novaj kernaj versioj (4.19+) alvoka agado estis plibonigita memory.stat, do ŝanĝi al ĉi tiu kerno riparis la problemon. Samtempe, ni havis ilojn por detekti problemajn nodojn en Kubernetes-aretoj, gracie malplenigi ilin kaj rekomenci ilin. Ni kombis ĉiujn aretojn, trovis nodojn kun sufiĉe alta latenteco kaj rekomencis ilin. Ĉi tio donis al ni tempon ĝisdatigi la OS sur la ceteraj serviloj.
Resumi
Ĉar ĉi tiu cimo ĉesigis RX-NIC-vico-pretigon dum centoj da milisekundoj, ĝi samtempe kaŭzis kaj altan latentecon sur mallongaj konektoj kaj mez-konekto latenteco, kiel inter MySQL-petoj kaj respondpakaĵoj.
Kompreni kaj konservi la agadon de la plej fundamentaj sistemoj, kiel Kubernetes, estas kritika por la fidindeco kaj rapideco de ĉiuj servoj bazitaj sur ili. Ĉiu sistemo, kiun vi administras, profitas de agado-plibonigoj de Kubernetes.
fonto: www.habr.com