Beberapa tahun yang lalu Kubernetes pada blog rasmi GitHub. Sejak itu, ia telah menjadi teknologi standard untuk menggunakan perkhidmatan. Kubernetes kini menguruskan sebahagian besar perkhidmatan dalaman dan awam. Apabila kluster kami berkembang dan keperluan prestasi menjadi lebih ketat, kami mula menyedari bahawa sesetengah perkhidmatan di Kubernetes secara sporadis mengalami kependaman yang tidak dapat dijelaskan oleh beban aplikasi itu sendiri.
Pada asasnya, aplikasi mengalami kependaman rangkaian rawak sehingga 100ms atau lebih, mengakibatkan tamat masa atau percubaan semula. Perkhidmatan dijangka dapat menjawab permintaan lebih cepat daripada 100ms. Tetapi ini adalah mustahil jika sambungan itu sendiri mengambil masa yang lama. Secara berasingan, kami memerhatikan pertanyaan MySQL yang sangat pantas yang sepatutnya mengambil masa milisaat, dan MySQL selesai dalam milisaat, tetapi dari perspektif aplikasi yang meminta, respons mengambil masa 100 ms atau lebih.
Ia serta-merta menjadi jelas bahawa masalah itu hanya berlaku apabila menyambung ke nod Kubernetes, walaupun jika panggilan itu datang dari luar Kubernetes. Cara paling mudah untuk menghasilkan semula masalah adalah dalam ujian , yang dijalankan dari mana-mana hos dalaman, menguji perkhidmatan Kubernetes pada port tertentu dan secara sporadis mendaftarkan kependaman tinggi. Dalam artikel ini, kita akan melihat bagaimana kita dapat mengesan punca masalah ini.
Menghapuskan kerumitan yang tidak perlu dalam rantaian yang membawa kepada kegagalan
Dengan menghasilkan semula contoh yang sama, kami ingin mengecilkan fokus masalah dan mengalih keluar lapisan kerumitan yang tidak perlu. Pada mulanya, terdapat terlalu banyak unsur dalam aliran antara Vegeta dan pod Kubernetes. Untuk mengenal pasti masalah rangkaian yang lebih mendalam, anda perlu menolak beberapa daripadanya.
Pelanggan (Vegeta) mencipta sambungan TCP dengan mana-mana nod dalam kelompok. Kubernetes beroperasi sebagai rangkaian tindanan (di atas rangkaian pusat data sedia ada) yang menggunakan , iaitu, ia merangkum paket IP rangkaian tindanan di dalam paket IP pusat data. Apabila menyambung ke nod pertama, terjemahan alamat rangkaian dilakukan (NAT) stateful untuk menterjemah alamat IP dan port nod Kubernetes kepada alamat IP dan port dalam rangkaian tindanan (khususnya, pod dengan aplikasi). Untuk paket masuk, urutan tindakan terbalik dilakukan. Ia adalah sistem yang kompleks dengan banyak keadaan dan banyak elemen yang sentiasa dikemas kini dan diubah apabila perkhidmatan digunakan dan dipindahkan.
Utiliti tcpdump dalam ujian Vegeta terdapat kelewatan semasa jabat tangan TCP (antara SYN dan SYN-ACK). Untuk mengalih keluar kerumitan yang tidak perlu ini, anda boleh gunakan hping3 untuk "ping" ringkas dengan paket SYN. Kami menyemak sama ada terdapat kelewatan dalam paket tindak balas, dan kemudian menetapkan semula sambungan. Kami boleh menapis data untuk hanya memasukkan paket yang lebih besar daripada 100ms dan mendapatkan cara yang lebih mudah untuk menghasilkan semula masalah daripada ujian lapisan rangkaian penuh 7 Vegeta. Berikut ialah "ping" nod Kubernetes menggunakan TCP SYN/SYN-ACK pada perkhidmatan "port nod" (30927) pada selang 10ms, ditapis mengikut respons paling perlahan:
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
Boleh segera membuat pemerhatian pertama. Berdasarkan nombor jujukan dan pemasaan, adalah jelas bahawa ini bukan kesesakan sekali sahaja. Kelewatan sering terkumpul dan akhirnya diproses.
Seterusnya, kami ingin mengetahui komponen mana yang mungkin terlibat dalam berlakunya kesesakan. Mungkin ini adalah beberapa daripada beratus-ratus peraturan iptables dalam NAT? Atau adakah terdapat sebarang masalah dengan terowong IPIP pada rangkaian? Satu cara untuk menyemak ini adalah untuk menguji setiap langkah sistem dengan menghapuskannya. Apa yang berlaku jika anda mengalih keluar logik NAT dan firewall, hanya meninggalkan bahagian IPIP:
Nasib baik, Linux memudahkan untuk mengakses lapisan tindanan IP secara langsung jika mesin berada pada rangkaian yang sama:
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
Berdasarkan keputusan, masalah masih kekal! Ini tidak termasuk iptables dan NAT. Jadi masalahnya ialah TCP? Mari lihat bagaimana ping ICMP biasa berlaku:
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
Keputusan menunjukkan bahawa masalah itu belum hilang. Mungkin ini adalah terowong IPIP? Mari permudahkan ujian lagi:
Adakah semua paket dihantar antara dua hos ini?
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
Kami telah memudahkan keadaan kepada dua nod Kubernetes yang menghantar satu sama lain sebarang paket, malah ping ICMP. Mereka masih melihat kependaman jika hos sasaran adalah "buruk" (sesetengahnya lebih teruk daripada yang lain).
Sekarang soalan terakhir: mengapa kelewatan hanya berlaku pada pelayan kube-node? Dan adakah ia berlaku apabila kube-node ialah penghantar atau penerima? Nasib baik, ini juga agak mudah untuk difikirkan dengan menghantar paket daripada hos di luar Kubernetes, tetapi dengan penerima "yang diketahui buruk" yang sama. Seperti yang anda lihat, masalahnya tidak hilang:
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
Kami kemudian akan menjalankan permintaan yang sama daripada kube-nod sumber sebelumnya kepada hos luaran (yang tidak termasuk hos sumber kerana ping termasuk kedua-dua komponen RX dan 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
Dengan memeriksa tangkapan paket kependaman, kami memperoleh beberapa maklumat tambahan. Khususnya, bahawa pengirim (bawah) melihat tamat masa ini, tetapi penerima (atas) tidak - lihat lajur Delta (dalam saat):
Di samping itu, jika anda melihat perbezaan dalam susunan paket TCP dan ICMP (mengikut nombor urutan) pada bahagian penerima, paket ICMP sentiasa tiba dalam urutan yang sama di mana ia dihantar, tetapi dengan masa yang berbeza. Pada masa yang sama, paket TCP kadangkala berselang, dan sebahagian daripadanya tersekat. Khususnya, jika anda memeriksa port paket SYN, ia adalah teratur di sisi penghantar, tetapi tidak di sisi penerima.
Terdapat perbezaan yang ketara dalam caranya pelayan moden (seperti yang terdapat di pusat data kami) memproses paket yang mengandungi TCP atau ICMP. Apabila paket tiba, penyesuai rangkaian "mencincangnya setiap sambungan", iaitu, ia cuba memecahkan sambungan ke dalam baris gilir dan menghantar setiap baris gilir ke teras pemproses yang berasingan. Untuk TCP, cincang ini termasuk alamat dan port IP sumber dan destinasi. Dalam erti kata lain, setiap sambungan dicincang (berpotensi) berbeza. Untuk ICMP, hanya alamat IP yang dicincang, kerana tiada port.
Satu lagi pemerhatian baharu: dalam tempoh ini kita melihat kelewatan ICMP pada semua komunikasi antara dua hos, tetapi TCP tidak. Ini memberitahu kita bahawa puncanya berkemungkinan berkaitan dengan pencincangan baris gilir RX: kesesakan hampir pasti dalam pemprosesan paket RX, bukan dalam penghantaran respons.
Ini menghapuskan penghantaran paket daripada senarai sebab yang mungkin. Kami kini tahu bahawa masalah pemprosesan paket adalah pada bahagian penerimaan pada beberapa pelayan kube-nod.
Memahami pemprosesan paket dalam kernel Linux
Untuk memahami sebab masalah berlaku pada penerima pada beberapa pelayan kube-nod, mari lihat bagaimana kernel Linux memproses paket.
Kembali kepada pelaksanaan tradisional yang paling mudah, kad rangkaian menerima paket dan menghantar kernel Linux bahawa terdapat pakej yang perlu diproses. Kernel menghentikan kerja lain, menukar konteks kepada pengendali gangguan, memproses paket, dan kemudian kembali ke tugas semasa.
Penukaran konteks ini perlahan: kependaman mungkin tidak ketara pada kad rangkaian 10Mbps pada tahun 90-an, tetapi pada kad 10G moden dengan daya pemprosesan maksimum 15 juta paket sesaat, setiap teras pelayan lapan teras kecil boleh diganggu berjuta-juta kali sesaat.
Untuk tidak sentiasa mengendalikan gangguan, bertahun-tahun yang lalu Linux menambah : API Rangkaian yang digunakan oleh semua pemacu moden untuk meningkatkan prestasi pada kelajuan tinggi. Pada kelajuan rendah kernel masih menerima gangguan daripada kad rangkaian dengan cara lama. Sebaik sahaja paket yang mencukupi tiba yang melebihi ambang, kernel menyahdayakan gangguan dan sebaliknya mula mengundi penyesuai rangkaian dan mengambil paket dalam ketulan. Pemprosesan dilakukan dalam softirq, iaitu, dalam selepas panggilan sistem dan perkakasan terganggu, apabila kernel (berbanding dengan ruang pengguna) sudah berjalan.
Ini lebih cepat, tetapi menyebabkan masalah yang berbeza. Jika terdapat terlalu banyak paket, maka sepanjang masa dibelanjakan untuk memproses paket dari kad rangkaian, dan proses ruang pengguna tidak mempunyai masa untuk benar-benar mengosongkan baris gilir ini (membaca dari sambungan TCP, dsb.). Akhirnya barisan penuh dan kami mula menjatuhkan paket. Dalam percubaan untuk mencari keseimbangan, kernel menetapkan belanjawan untuk bilangan maksimum paket yang diproses dalam konteks softirq. Sebaik sahaja belanjawan ini melebihi, rangkaian berasingan akan dibangkitkan ksoftirqd (anda akan melihat salah seorang daripada mereka dalam ps setiap teras) yang mengendalikan softirqs ini di luar laluan syscall/interrupt biasa. Urutan ini dijadualkan menggunakan penjadual proses standard, yang cuba memperuntukkan sumber secara adil.
Setelah mengkaji bagaimana kernel memproses paket, anda dapat melihat bahawa terdapat kemungkinan kesesakan tertentu. Jika panggilan softirq kurang kerap diterima, paket perlu menunggu beberapa lama untuk diproses dalam baris gilir RX pada kad rangkaian. Ini mungkin disebabkan oleh beberapa tugas yang menyekat teras pemproses, atau sesuatu yang lain menghalang teras daripada menjalankan softirq.
Menyempitkan pemprosesan kepada inti atau kaedah
Kelewatan Softirq hanyalah tekaan buat masa ini. Tetapi ia masuk akal, dan kami tahu kami melihat sesuatu yang hampir serupa. Jadi langkah seterusnya ialah mengesahkan teori ini. Dan jika ia disahkan, maka cari sebab kelewatan.
Mari kembali ke paket lambat kami:
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
Seperti yang dibincangkan sebelum ini, paket ICMP ini dicincang ke dalam satu baris gilir RX NIC dan diproses oleh satu teras CPU. Jika kita ingin memahami cara Linux berfungsi, adalah berguna untuk mengetahui di mana (pada teras CPU yang mana) dan bagaimana (softirq, ksoftirqd) pakej ini diproses untuk menjejaki proses tersebut.
Kini tiba masanya untuk menggunakan alat yang membolehkan anda memantau kernel Linux dalam masa nyata. Di sini kami gunakan . Set alatan ini membolehkan anda menulis atur cara C kecil yang mengaitkan fungsi sewenang-wenangnya dalam kernel dan menampan peristiwa tersebut ke dalam atur cara Python ruang pengguna yang boleh memprosesnya dan mengembalikan hasilnya kepada anda. Cangkuk untuk fungsi sewenang-wenang dalam kernel adalah perkara yang rumit, tetapi utiliti itu direka untuk keselamatan maksimum dan direka untuk mengesan jenis isu pengeluaran yang tidak mudah dihasilkan semula dalam persekitaran ujian atau pembangunan.
Pelan di sini adalah mudah: kami tahu bahawa kernel memproses ping ICMP ini, jadi kami akan meletakkan cangkuk pada fungsi kernel , yang menerima paket permintaan gema ICMP masuk dan memulakan penghantaran respons gema ICMP. Kita boleh mengenal pasti paket dengan meningkatkan nombor icmp_seq, yang menunjukkan hping3 di atas.
Kod nampak rumit, tetapi tidaklah seram seperti yang disangka. Fungsi icmp_echo menyampaikan struct sk_buff *skb: Ini adalah paket dengan "permintaan gema". Kita boleh menjejakinya, menarik keluar urutannya echo.sequence (yang dibandingkan dengan icmp_seq oleh hping3 Π²ΡΡΠ΅), dan hantar ke ruang pengguna. Ia juga mudah untuk menangkap nama/id proses semasa. Berikut adalah hasil yang kita lihat secara langsung semasa kernel memproses paket:
TGID PID Proses Nama 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 Prometheus 775 0 0 11 776 0 0 swapper/11 777 0 0 spokes-report-s 11
Perlu diingatkan di sini bahawa dalam konteks softirq proses yang membuat panggilan sistem akan muncul sebagai "proses" sedangkan sebenarnya kernel yang memproses paket dengan selamat dalam konteks kernel.
Dengan alat ini kita boleh mengaitkan proses tertentu dengan pakej tertentu yang menunjukkan kelewatan hping3. Jom permudahkan grep pada tangkapan ini untuk nilai tertentu icmp_seq. Paket yang sepadan dengan nilai icmp_seq di atas telah dicatat bersama-sama dengan RTT mereka yang kami perhatikan di atas (dalam kurungan ialah nilai RTT yang dijangkakan untuk paket yang kami tapis kerana nilai RTT kurang daripada 50 ms):
NAMA PROSES PID TGID ICMP_SEQ ** RTT -- 10137 10436 kadvisor 1951 10137 10436 kadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftirqd 11 1954 ksoftirqd 89 76 ksoftirqd /76 11 ** 1955ms 79 76 ksoftirqd/ 76 11 ** 1956ms 69 76 ksoftirqd/76 11 ** 1957ms 59 76 ksoftirqd/76 11 ** (1958ms) 49 76 ksoftirqd/76 11 ** (1959ms) 39 76 k76softirqd/11 1960 ** (29ms) 76 76 ksoftirqd/11 1961 ** (19ms) 76 76 k11softirqd 1962 9 k10137softirqd (10436ms) ** irqd/ 2068 10137 ** (10436ms) 2069 76 ksoftirqd/76 11 ** (2070ms) -- 75 76 cadvisor 76 11 2071 cadvisor 65 76 76 ksoftirqd 11 2072 ksoftirqd 55/76 ksoftirqd 76qd /11 2073 ** 45ms 76 76 ksoftirqd/ 11 2074 ** 35ms 76 76 ksoftirqd/11 2075 ** (25ms) 76 76 ksoftirqd/11 2076 ** (15ms) 76 76 ksoftirqd/11 2077 ** (5ms) XNUMX ms) XNUMX ms) ) XNUMX XNUMX ksoftirqd/XNUMX XNUMX ** (XNUMXms)
Hasilnya memberitahu kita beberapa perkara. Pertama, semua pakej ini diproses mengikut konteks ksoftirqd/11. Ini bermakna bahawa untuk pasangan mesin tertentu ini, paket ICMP telah dicincang ke teras 11 di hujung penerima. Kami juga melihat bahawa apabila terdapat kesesakan, terdapat paket yang diproses dalam konteks panggilan sistem cadvisor. Kemudian ksoftirqd mengambil alih tugas dan memproses baris gilir terkumpul: tepat bilangan paket yang telah terkumpul selepas itu cadvisor.
Hakikat bahawa sejurus sebelum ia sentiasa berfungsi cadvisor, membayangkan penglibatannya dalam masalah itu. Ironinya, tujuannya - "analisis penggunaan sumber dan ciri prestasi bekas yang sedang berjalan" dan bukannya menyebabkan isu prestasi ini.
Seperti aspek bekas yang lain, ini semua adalah alat yang sangat maju dan boleh dijangka mengalami masalah prestasi dalam beberapa keadaan yang tidak dijangka.
Apakah yang dilakukan oleh cadvisor yang melambatkan baris gilir paket?
Kami kini mempunyai pemahaman yang cukup baik tentang bagaimana ranap sistem berlaku, proses apa yang menyebabkannya, dan pada CPU yang mana. Kami melihat bahawa disebabkan penyekatan keras, kernel Linux tidak mempunyai masa untuk menjadualkan ksoftirqd. Dan kami melihat bahawa paket diproses dalam konteks cadvisor. Adalah logik untuk menganggapnya cadvisor melancarkan syscall perlahan, selepas itu semua paket terkumpul pada masa itu diproses:
Ini adalah teori, tetapi bagaimana untuk mengujinya? Apa yang boleh kita lakukan ialah mengesan teras CPU sepanjang proses ini, cari titik di mana bilangan paket melebihi bajet dan ksoftirqd dipanggil, dan kemudian lihat lebih jauh ke belakang untuk melihat apa sebenarnya yang sedang berjalan pada teras CPU sebelum titik itu . Ia seperti x-ray CPU setiap beberapa milisaat. Ia akan kelihatan seperti ini:
Dengan mudah, semua ini boleh dilakukan dengan alat sedia ada. Sebagai contoh, menyemak teras CPU tertentu pada frekuensi tertentu dan boleh menjana jadual panggilan ke sistem yang sedang berjalan, termasuk ruang pengguna dan kernel Linux. Anda boleh mengambil rekod ini dan memprosesnya menggunakan garpu kecil program daripada Brendan Gregg, yang mengekalkan susunan surih tindanan. Kami boleh menyimpan surih tindanan satu baris setiap 1 ms, dan kemudian menyerlahkan dan menyimpan sampel 100 milisaat sebelum surih mencecah 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
Berikut adalah keputusannya:
(ΡΠΎΡΠ½ΠΈ ΡΠ»Π΅Π΄ΠΎΠ², ΠΊΠΎΡΠΎΡΡΠ΅ Π²ΡΠ³Π»ΡΠ΄ΡΡ ΠΏΠΎΡ
ΠΎΠΆΠΈΠΌΠΈ)
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
Terdapat banyak perkara di sini, tetapi perkara utama ialah kita menemui corak "cadvisor before ksoftirqd" yang kita lihat sebelum ini dalam pengesan ICMP. Apakah maksudnya?
Setiap baris ialah jejak CPU pada satu masa tertentu. Setiap panggilan ke bawah tindanan pada baris dipisahkan oleh koma bertitik. Di tengah-tengah baris kita melihat syscall dipanggil: read(): .... ;do_syscall_64;sys_read; .... Jadi cadvisor menghabiskan banyak masa pada panggilan sistem read()berkaitan dengan fungsi mem_cgroup_* (atas timbunan panggilan/hujung talian).
Menyusahkan untuk melihat dalam jejak panggilan apa sebenarnya yang dibaca, jadi mari kita jalankan strace dan mari lihat apa yang dilakukan oleh cadvisor dan cari panggilan sistem lebih lama daripada 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>
Seperti yang anda jangkakan, kami melihat panggilan perlahan di sini read(). Daripada kandungan operasi baca dan konteks mem_cgroup jelaslah bahawa cabaran-cabaran ini read() rujuk fail memory.stat, yang menunjukkan penggunaan memori dan had cgroup (teknologi pengasingan sumber Docker). Alat cadvisor menanyakan fail ini untuk mendapatkan maklumat penggunaan sumber untuk bekas. Mari semak sama ada kernel atau cadvisor melakukan sesuatu yang tidak dijangka:
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 ~ $
Sekarang kita boleh menghasilkan semula pepijat dan memahami bahawa kernel Linux menghadapi patologi.
Mengapakah operasi membaca sangat perlahan?
Pada peringkat ini, lebih mudah untuk mencari mesej daripada pengguna lain tentang masalah yang sama. Ternyata, dalam penjejak cadvisor pepijat ini dilaporkan sebagai , cuma tiada siapa yang perasan bahawa kependaman juga ditunjukkan secara rawak dalam timbunan rangkaian. Memang disedari bahawa kadvisor menggunakan lebih banyak masa CPU daripada yang dijangkakan, tetapi ini tidak begitu diutamakan, kerana pelayan kami mempunyai banyak sumber CPU, jadi masalahnya tidak dikaji dengan teliti.
Masalahnya ialah cgroups mengambil kira penggunaan memori dalam ruang nama (bekas). Apabila semua proses dalam cgroup ini keluar, Docker melepaskan cgroup memori. Walau bagaimanapun, "memori" bukan hanya memproses memori. Walaupun memori proses itu sendiri tidak lagi digunakan, nampaknya kernel masih memberikan kandungan cache, seperti dentri dan inod (metadata direktori dan fail), yang dicache dalam cgroup memori. Daripada huraian masalah:
zombie cgroups: cgroups yang tidak mempunyai proses dan telah dipadamkan, tetapi masih mempunyai memori yang diperuntukkan (dalam kes saya, dari cache dentry, tetapi ia juga boleh diperuntukkan dari cache halaman atau tmpfs).
Semakan kernel terhadap semua halaman dalam cache apabila membebaskan cgroup boleh menjadi sangat perlahan, jadi proses malas dipilih: tunggu sehingga halaman ini diminta semula, dan kemudian akhirnya kosongkan cgroup apabila memori sebenarnya diperlukan. Sehingga ini, cgroup masih diambil kira semasa mengumpul statistik.
Dari sudut prestasi, mereka mengorbankan memori untuk prestasi: mempercepatkan pembersihan awal dengan meninggalkan beberapa memori yang disimpan di cache. Ini baik. Apabila kernel menggunakan memori terakhir cache, cgroup akhirnya dibersihkan, jadi ia tidak boleh dipanggil "kebocoran". Malangnya, pelaksanaan khusus mekanisme carian memory.stat dalam versi kernel ini (4.9), digabungkan dengan jumlah memori yang besar pada pelayan kami, bermakna ia mengambil masa yang lebih lama untuk memulihkan data cache terkini dan membersihkan zombi cgroup.
Ternyata beberapa nod kami mempunyai begitu banyak zombi cgroup sehingga bacaan dan kependaman melebihi satu saat.
Penyelesaian untuk masalah cadvisor adalah dengan segera mengosongkan cache dentri/inod di seluruh sistem, yang segera menghapuskan kependaman baca serta kependaman rangkaian pada hos, kerana mengosongkan cache menghidupkan halaman cgroup zombie yang dicache dan membebaskannya juga. Ini bukan penyelesaian, tetapi ia mengesahkan punca masalah.
Ternyata dalam versi kernel yang lebih baru (4.19+) prestasi panggilan telah dipertingkatkan memory.stat, jadi beralih kepada kernel ini menyelesaikan masalah. Pada masa yang sama, kami mempunyai alat untuk mengesan nod bermasalah dalam kelompok Kubernetes, mengalirkannya dengan anggun dan but semula. Kami menyisir semua kelompok, menemui nod dengan kependaman yang cukup tinggi dan but semula mereka. Ini memberi kami masa untuk mengemas kini OS pada pelayan yang tinggal.
Merumuskan
Oleh kerana pepijat ini menghentikan pemprosesan baris gilir RX NIC selama ratusan milisaat, ia pada masa yang sama menyebabkan kependaman tinggi pada sambungan pendek dan kependaman pertengahan sambungan, seperti antara permintaan MySQL dan paket tindak balas.
Memahami dan mengekalkan prestasi sistem yang paling asas, seperti Kubernetes, adalah penting untuk kebolehpercayaan dan kelajuan semua perkhidmatan berdasarkannya. Setiap sistem yang anda jalankan mendapat manfaat daripada peningkatan prestasi Kubernetes.
Sumber: www.habr.com