Beberapa tahun yang lalu Kubernetes di blog resmi GitHub. Sejak itu, ini telah menjadi teknologi standar untuk menyebarkan layanan. Kubernetes kini mengelola sebagian besar layanan internal dan publik. Seiring dengan pertumbuhan klaster kami dan persyaratan kinerja yang semakin ketat, kami mulai memperhatikan bahwa beberapa layanan di Kubernetes secara sporadis mengalami latensi yang tidak dapat dijelaskan oleh beban aplikasi itu sendiri.
Pada dasarnya, aplikasi mengalami latensi jaringan acak hingga 100 md atau lebih, yang mengakibatkan waktu habis atau percobaan ulang. Layanan diharapkan mampu merespons permintaan jauh lebih cepat dari 100 ms. Namun hal ini tidak mungkin dilakukan jika koneksinya sendiri memakan waktu lama. Secara terpisah, kami mengamati kueri MySQL yang sangat cepat yang memerlukan waktu milidetik, dan MySQL menyelesaikannya dalam milidetik, namun dari sudut pandang aplikasi yang meminta, responsnya memerlukan waktu 100 ms atau lebih.
Segera menjadi jelas bahwa masalah hanya terjadi ketika terhubung ke node Kubernetes, meskipun panggilan tersebut datang dari luar Kubernetes. Cara termudah untuk mereproduksi masalah adalah dalam ujian , yang dijalankan dari host internal mana pun, menguji layanan Kubernetes pada port tertentu, dan secara sporadis mencatat latensi tinggi. Pada artikel ini, kita akan melihat bagaimana kami dapat melacak penyebab masalah ini.
Menghilangkan kompleksitas yang tidak perlu dalam rantai yang menyebabkan kegagalan
Dengan mereproduksi contoh yang sama, kami ingin mempersempit fokus masalah dan menghilangkan lapisan kompleksitas yang tidak perlu. Awalnya, ada terlalu banyak elemen dalam aliran antara Vegeta dan pod Kubernetes. Untuk mengidentifikasi masalah jaringan yang lebih dalam, Anda perlu menyingkirkan beberapa di antaranya.
Klien (Vegeta) membuat koneksi TCP dengan node mana pun di cluster. Kubernetes beroperasi sebagai jaringan overlay (di atas jaringan pusat data yang ada) yang menggunakan , yaitu merangkum paket IP dari jaringan overlay di dalam paket IP pusat data. Saat menghubungkan ke node pertama, terjemahan alamat jaringan dilakukan (NAT) stateful untuk menerjemahkan alamat IP dan port node Kubernetes ke alamat IP dan port di jaringan overlay (khususnya, pod dengan aplikasi). Untuk paket masuk, urutan tindakan sebaliknya dilakukan. Ini adalah sistem yang kompleks dengan banyak negara dan banyak elemen yang terus diperbarui dan diubah seiring dengan penyebaran dan perpindahan layanan.
Π° tcpdump pada pengujian Vegeta terdapat delay pada saat handshake TCP (antara SYN dan SYN-ACK). Untuk menghilangkan kerumitan yang tidak perlu ini, Anda dapat menggunakan hping3 untuk βpingβ sederhana dengan paket SYN. Kami memeriksa apakah ada penundaan dalam paket respons, dan kemudian mengatur ulang koneksi. Kami dapat memfilter data agar hanya menyertakan paket yang lebih besar dari 100 md dan mendapatkan cara yang lebih mudah untuk mereproduksi masalah dibandingkan pengujian lapisan 7 jaringan lengkap Vegeta. Berikut adalah "ping" node Kubernetes menggunakan TCP SYN/SYN-ACK pada layanan "port node" (30927) dengan interval 10 md, difilter berdasarkan respons paling lambat:
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
Bisa langsung melakukan observasi pertama. Dilihat dari nomor urut dan waktunya, jelas bahwa ini bukan kemacetan yang hanya terjadi satu kali saja. Penundaan sering kali terakumulasi dan akhirnya diproses.
Selanjutnya kita ingin mengetahui komponen apa saja yang mungkin terlibat dalam terjadinya kemacetan. Mungkin ini beberapa dari ratusan aturan iptables di NAT? Atau ada masalah dengan IPIP tunneling di jaringan? Salah satu cara untuk memeriksanya adalah dengan menguji setiap langkah sistem dengan menghilangkannya. Apa yang terjadi jika Anda menghapus logika NAT dan firewall, hanya menyisakan bagian IPIP:
Untungnya, Linux memudahkan untuk mengakses lapisan overlay IP secara langsung jika mesin berada di jaringan 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
Dilihat dari hasilnya, masalahnya masih tetap ada! Ini tidak termasuk iptables dan NAT. Jadi masalahnya adalah TCP? Mari kita lihat bagaimana ping ICMP biasa berjalan:
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
Hasilnya menunjukkan bahwa masalahnya belum hilang. Mungkinkah ini terowongan IPIP? Mari kita sederhanakan pengujiannya lebih lanjut:
Apakah semua paket dikirim antara kedua host 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 menyederhanakan situasinya menjadi dua node Kubernetes yang saling mengirim paket apa pun, bahkan ping ICMP. Mereka masih melihat latensi jika host targetnya "buruk" (beberapa lebih buruk dari yang lain).
Sekarang pertanyaan terakhir: mengapa penundaan hanya terjadi pada server kube-node? Dan apakah itu terjadi ketika kube-node menjadi pengirim atau penerima? Untungnya, hal ini juga cukup mudah untuk diketahui dengan mengirimkan paket dari host di luar Kubernetes, tetapi dengan penerima βyang diketahui burukβ yang sama. Seperti yang Anda lihat, masalahnya belum 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 dari kube-node sumber sebelumnya ke host eksternal (tidak termasuk host sumber karena ping mencakup 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 latensi, kami memperoleh beberapa informasi tambahan. Khususnya, pengirim (bawah) melihat batas waktu ini, namun penerima (atas) tidak - lihat kolom Delta (dalam hitungan detik):
Selain itu, jika melihat perbedaan urutan paket TCP dan ICMP (berdasarkan nomor urut) di sisi penerima, paket ICMP selalu sampai dalam urutan yang sama dengan pengirimannya, namun dengan waktu yang berbeda. Pada saat yang sama, paket TCP terkadang disisipkan, dan beberapa di antaranya macet. Secara khusus, jika Anda memeriksa port paket SYN, port tersebut berada di sisi pengirim, tetapi tidak di sisi penerima.
Ada perbedaan halus dalam caranya server modern (seperti yang ada di pusat data kami) memproses paket yang berisi TCP atau ICMP. Ketika sebuah paket tiba, adaptor jaringan "men-hashnya per koneksi", yaitu mencoba memecah koneksi menjadi antrian dan mengirim setiap antrian ke inti prosesor yang terpisah. Untuk TCP, hash ini mencakup alamat IP dan port sumber dan tujuan. Dengan kata lain, setiap koneksi di-hash (berpotensi) berbeda. Untuk ICMP, hanya alamat IP yang di-hash, karena tidak ada port.
Pengamatan baru lainnya: selama periode ini kita melihat penundaan ICMP pada semua komunikasi antara dua host, namun TCP tidak. Hal ini memberitahu kita bahwa penyebabnya mungkin terkait dengan hashing antrian RX: kemacetan hampir pasti terjadi pada pemrosesan paket RX, bukan pada pengiriman respons.
Ini menghilangkan pengiriman paket dari daftar kemungkinan penyebabnya. Kita sekarang tahu bahwa masalah pemrosesan paket ada di sisi penerima di beberapa server kube-node.
Memahami pemrosesan paket di kernel Linux
Untuk memahami mengapa masalah terjadi pada penerima di beberapa server kube-node, mari kita lihat bagaimana kernel Linux memproses paket.
Kembali ke implementasi tradisional yang paling sederhana, kartu jaringan menerima paket dan mengirimkannya kernel Linux yang ada paketnya perlu diproses. Kernel menghentikan pekerjaan lain, mengalihkan konteks ke pengendali interupsi, memproses paket, dan kemudian kembali ke tugas saat ini.
Peralihan konteks ini lambat: latensi mungkin tidak terlihat pada kartu jaringan 10Mbps di tahun 90an, namun pada kartu 10G modern dengan throughput maksimum 15 juta paket per detik, setiap inti dari server kecil delapan inti dapat diinterupsi jutaan kali per detik.
Agar tidak terus-menerus menangani interupsi, Linux menambahkan beberapa tahun yang lalu : API Jaringan yang digunakan semua driver modern untuk meningkatkan kinerja pada kecepatan tinggi. Pada kecepatan rendah kernel masih menerima interupsi dari kartu jaringan dengan cara yang lama. Setelah cukup banyak paket tiba yang melebihi ambang batas, kernel menonaktifkan interupsi dan mulai melakukan polling pada adaptor jaringan dan mengambil paket dalam beberapa bagian. Pemrosesan dilakukan di softirq, yaitu di setelah panggilan sistem dan interupsi perangkat keras, ketika kernel (sebagai lawan dari ruang pengguna) sudah berjalan.
Ini jauh lebih cepat, namun menyebabkan masalah yang berbeda. Jika ada terlalu banyak paket, maka seluruh waktu dihabiskan untuk memproses paket dari kartu jaringan, dan proses ruang pengguna tidak punya waktu untuk benar-benar mengosongkan antrian ini (membaca dari koneksi TCP, dll.). Akhirnya antrian terisi dan kami mulai mengirimkan paket. Dalam upaya untuk menemukan keseimbangan, kernel menetapkan anggaran untuk jumlah maksimum paket yang diproses dalam konteks softirq. Setelah anggaran ini terlampaui, thread terpisah akan dibangunkan ksoftirqd (Anda akan melihat salah satunya di ps per inti) yang menangani perangkat lunak ini di luar jalur syscall/interupsi normal. Thread ini dijadwalkan menggunakan penjadwal proses standar, yang berupaya mengalokasikan sumber daya secara adil.
Setelah mempelajari bagaimana kernel memproses paket, Anda dapat melihat bahwa ada kemungkinan terjadinya kemacetan. Jika panggilan softirq lebih jarang diterima, paket harus menunggu beberapa saat untuk diproses dalam antrian RX pada kartu jaringan. Hal ini mungkin disebabkan oleh beberapa tugas yang memblokir inti prosesor, atau ada hal lain yang mencegah inti menjalankan softirq.
Mempersempit pemrosesan hingga ke inti atau metode
Penundaan Softirq hanyalah dugaan untuk saat ini. Tapi itu masuk akal, dan kami tahu kami melihat sesuatu yang sangat mirip. Jadi langkah selanjutnya adalah mengkonfirmasi teori ini. Dan jika sudah dikonfirmasi, cari tahu alasan penundaannya.
Mari kembali ke paket lambat kita:
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 dibahas sebelumnya, paket ICMP ini di-hash ke dalam satu antrian RX NIC dan diproses oleh satu inti CPU. Jika kita ingin memahami cara kerja Linux, ada gunanya mengetahui di mana (pada inti CPU yang mana) dan bagaimana (softirq, ksoftirqd) paket-paket ini diproses untuk melacak prosesnya.
Sekarang saatnya menggunakan alat yang memungkinkan Anda memantau kernel Linux secara real time. Di sini kami menggunakan . Seperangkat alat ini memungkinkan Anda untuk menulis program C kecil yang mengaitkan fungsi arbitrer di kernel dan menyangga kejadian tersebut ke dalam program Python ruang pengguna yang dapat memprosesnya dan mengembalikan hasilnya kepada Anda. Kait untuk fungsi sewenang-wenang di kernel adalah masalah yang rumit, tetapi utilitas ini dirancang untuk keamanan maksimum dan dirancang untuk melacak jenis masalah produksi yang tidak mudah direproduksi dalam lingkungan pengujian atau pengembangan.
Rencananya di sini sederhana: kita tahu bahwa kernel memproses ping ICMP ini, jadi kita akan mengaitkan fungsi kernel , yang menerima paket permintaan gema ICMP yang masuk dan memulai pengiriman respons gema ICMP. Kita dapat mengidentifikasi sebuah paket dengan menambah nomor icmp_seq yang ditampilkan hping3 lebih tinggi.
kode terlihat rumit, namun tidak seseram kelihatannya. Fungsi icmp_echo mentransmisikan struct sk_buff *skb: Ini adalah paket dengan "permintaan gema". Kita bisa melacaknya, mengeluarkan urutannya echo.sequence (yang dibandingkan dengan icmp_seq oleh hping3 Π²ΡΡΠ΅), dan mengirimkannya ke ruang pengguna. Juga mudah untuk menangkap nama/id proses saat ini. Di bawah ini adalah hasil yang kita lihat secara langsung saat kernel memproses paket:
NAMA PROSES PID TGID 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 swapper/11 776 0 0 swapper/11 777 0 0 11 swapper/778 4512 4542 779 laporan-jari-jari XNUMX
Perlu dicatat di sini bahwa dalam konteksnya softirq proses yang melakukan panggilan sistem akan muncul sebagai "proses" padahal sebenarnya kernellah yang memproses paket dengan aman dalam konteks kernel.
Dengan alat ini kita dapat mengaitkan proses tertentu dengan paket tertentu yang menunjukkan penundaan hping3. Mari kita buat menjadi sederhana grep pada penangkapan ini untuk nilai-nilai tertentu icmp_seq. Paket yang cocok dengan nilai icmp_seq di atas dicatat bersama dengan RTT yang kami amati di atas (dalam tanda kurung adalah nilai RTT yang diharapkan untuk paket yang kami filter karena nilai RTT kurang dari 50 ms):
NAMA PROSES PID TGID ICMP_SEQ **RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 **99ms 76 76 ksoftirqd/11 1954 **89ms 76 76 ksoftir 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 ksoft irqd/ 11 1961** (19ms) 76 76 ksoftirqd/11 1962 ** (9ms) -- 10137 10436 cadvisor 2068 10137 10436 cadvisor 2069 76 76 ksoftirqd/11 2070 **75ms 76 76 ksoftirqd/11 2071 65 ** 76 md 76 11 ksoftirqd/ 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 ** (76ms ) 76 11 ksoftirqd/2077 5** (XNUMXms)
Hasilnya memberi tahu kita beberapa hal. Pertama, semua paket ini diproses berdasarkan konteksnya ksoftirqd/11. Ini berarti bahwa untuk sepasang mesin khusus ini, paket ICMP di-hash ke inti 11 di sisi penerima. Kita juga melihat bahwa setiap kali terjadi kemacetan, ada paket yang diproses dalam konteks panggilan sistem cadvisor. Kemudian ksoftirqd mengambil alih tugas dan memproses antrian yang terakumulasi: persis dengan jumlah paket yang terakumulasi setelahnya cadvisor.
Fakta bahwa sebelumnya selalu berhasil cadvisor, menyiratkan keterlibatannya dalam masalah tersebut. Ironisnya, tujuannya - "menganalisis penggunaan sumber daya dan karakteristik kinerja dari container yang sedang berjalan" daripada menyebabkan masalah kinerja ini.
Seperti aspek container lainnya, ini semua adalah alat yang sangat canggih dan diperkirakan akan mengalami masalah kinerja dalam keadaan yang tidak terduga.
Apa yang dilakukan cadvisor yang memperlambat antrian paket?
Kami sekarang memiliki pemahaman yang cukup baik tentang bagaimana crash terjadi, proses apa yang menyebabkannya, dan pada CPU yang mana. Kami melihat bahwa karena pemblokiran yang sulit, kernel Linux tidak punya waktu untuk menjadwalkan ksoftirqd. Dan kami melihat bahwa paket diproses dalam konteks cadvisor. Masuk akal untuk berasumsi demikian cadvisor meluncurkan syscall lambat, setelah itu semua paket yang terakumulasi pada saat itu diproses:
Ini teori, tapi bagaimana cara mengujinya? Apa yang bisa kita lakukan adalah melacak inti CPU selama proses ini, menemukan titik di mana jumlah paket melebihi anggaran dan ksoftirqd dipanggil, lalu melihat lebih jauh ke belakang untuk melihat apa sebenarnya yang berjalan pada inti CPU sebelum titik tersebut. . Ini seperti melakukan rontgen pada CPU setiap beberapa milidetik. Ini akan terlihat seperti ini:
Mudahnya, semua ini dapat dilakukan dengan alat yang ada. Misalnya, memeriksa inti CPU tertentu pada frekuensi tertentu dan dapat menghasilkan jadwal panggilan ke sistem yang sedang berjalan, termasuk ruang pengguna dan kernel Linux. Anda dapat mengambil catatan ini dan memprosesnya menggunakan cabang kecil dari program dari Brendan Gregg, yang menjaga urutan jejak tumpukan. Kita dapat menyimpan pelacakan tumpukan satu baris setiap 1 ms, lalu menyorot dan menyimpan sampel 100 milidetik sebelum pelacakan terjadi 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 hasilnya:
(ΡΠΎΡΠ½ΠΈ ΡΠ»Π΅Π΄ΠΎΠ², ΠΊΠΎΡΠΎΡΡΠ΅ Π²ΡΠ³Π»ΡΠ΄ΡΡ ΠΏΠΎΡ
ΠΎΠΆΠΈΠΌΠΈ)
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
Ada banyak hal disini, tapi yang terpenting adalah kita menemukan pola βcadvisor sebelum ksoftirqdβ yang kita lihat sebelumnya di tracer ICMP. Apa artinya?
Setiap baris adalah jejak CPU pada titik waktu tertentu. Setiap pemanggilan tumpukan pada suatu baris dipisahkan dengan titik koma. Di tengah baris kita melihat syscall dipanggil: read(): .... ;do_syscall_64;sys_read; .... Jadi cadvisor menghabiskan banyak waktu pada system call read()berkaitan dengan fungsi mem_cgroup_* (bagian atas tumpukan panggilan/akhir saluran).
Tidak nyaman untuk melihat jejak panggilan apa yang sebenarnya sedang dibaca, jadi mari kita jalankan strace dan mari kita lihat apa yang dilakukan cadvisor dan temukan panggilan sistem yang lebih lama dari 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 duga, kami melihat panggilan lambat di sini read(). Dari isi operasi baca dan konteks mem_cgroup jelas bahwa tantangan-tantangan ini read() lihat filenya memory.stat, yang menunjukkan penggunaan memori dan batas cgroup (teknologi isolasi sumber daya Docker). Alat cadvisor menanyakan file ini untuk mendapatkan informasi penggunaan sumber daya untuk kontainer. Mari kita periksa apakah kernel atau cadvisor melakukan sesuatu yang tidak terduga:
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 kami dapat mereproduksi bug tersebut dan memahami bahwa kernel Linux sedang menghadapi suatu patologi.
Mengapa operasi baca sangat lambat?
Pada tahap ini, lebih mudah untuk menemukan pesan dari pengguna lain tentang masalah serupa. Ternyata, di pelacak cadvisor, bug ini dilaporkan sebagai , hanya saja tidak ada yang memperhatikan bahwa latensi juga tercermin secara acak di tumpukan jaringan. Memang diketahui bahwa cadvisor memakan lebih banyak waktu CPU daripada yang diharapkan, namun hal ini tidak terlalu dianggap penting, karena server kami memiliki banyak sumber daya CPU, sehingga masalahnya tidak dipelajari dengan cermat.
Masalahnya adalah cgroup memperhitungkan penggunaan memori dalam namespace (container). Ketika semua proses di cgroup ini keluar, Docker melepaskan cgroup memori. Namun, "memori" bukan sekadar memori proses. Meskipun memori proses itu sendiri tidak lagi digunakan, tampaknya kernel masih memberikan konten yang di-cache, seperti dentries dan inode (metadata direktori dan file), yang di-cache di cgroup memori. Dari deskripsi masalah:
cgroup zombie: cgroup yang tidak memiliki proses dan telah dihapus, tetapi masih memiliki alokasi memori (dalam kasus saya, dari cache dentry, tetapi juga dapat dialokasikan dari cache halaman atau tmpfs).
Pemeriksaan kernel terhadap semua halaman dalam cache ketika membebaskan cgroup bisa sangat lambat, jadi proses yang lambat dipilih: tunggu sampai halaman-halaman ini diminta lagi, dan terakhir hapus cgroup ketika memori benar-benar dibutuhkan. Hingga saat ini, cgroup masih diperhitungkan saat mengumpulkan statistik.
Dari sudut pandang kinerja, mereka mengorbankan memori demi kinerja: mempercepat pembersihan awal dengan meninggalkan beberapa memori cache. Ini baik-baik saja. Ketika kernel menggunakan sisa memori cache, cgroup pada akhirnya akan dihapus, sehingga tidak dapat disebut sebagai "kebocoran". Sayangnya, penerapan mekanisme pencarian spesifik memory.stat dalam versi kernel ini (4.9), dikombinasikan dengan jumlah memori yang besar di server kami, berarti diperlukan waktu lebih lama untuk memulihkan data cache terbaru dan menghapus zombie cgroup.
Ternyata beberapa node kami memiliki begitu banyak cgroup zombie sehingga pembacaan dan latensinya melebihi satu detik.
Solusi untuk masalah cadvisor adalah dengan segera mengosongkan cache dentries/inodes di seluruh sistem, yang segera menghilangkan latensi baca serta latensi jaringan pada host, karena membersihkan cache akan mengaktifkan halaman cgroup zombie yang di-cache dan membebaskannya juga. Ini bukan solusi, namun memastikan penyebab masalahnya.
Ternyata di versi kernel yang lebih baru (4.19+) kinerja panggilan ditingkatkan memory.stat, jadi beralih ke kernel ini memperbaiki masalahnya. Pada saat yang sama, kami memiliki alat untuk mendeteksi node bermasalah di cluster Kubernetes, menguras node tersebut dengan baik, dan melakukan boot ulang. Kami menyisir semua cluster, menemukan node dengan latensi cukup tinggi dan mem-boot ulangnya. Ini memberi kami waktu untuk memperbarui OS di server yang tersisa.
Menyimpulkan
Karena bug ini menghentikan pemrosesan antrean RX NIC selama ratusan milidetik, bug ini secara bersamaan menyebabkan latensi tinggi pada koneksi pendek dan latensi koneksi tengah, seperti antara permintaan MySQL dan paket respons.
Memahami dan menjaga kinerja sistem yang paling mendasar, seperti Kubernetes, sangat penting untuk keandalan dan kecepatan semua layanan yang berbasis pada sistem tersebut. Setiap sistem yang Anda jalankan mendapat manfaat dari peningkatan kinerja Kubernetes.
Sumber: www.habr.com