چند سال پیش Kubernetes قبلا بحث شده است در وبلاگ رسمی GitHub. از آن زمان، این فناوری به فناوری استاندارد برای استقرار خدمات تبدیل شده است. Kubernetes اکنون بخش قابل توجهی از خدمات داخلی و عمومی را مدیریت می کند. وقتی خوشه‌های ما رشد کردند و الزامات عملکرد سخت‌تر شدند، متوجه شدیم که برخی از سرویس‌ها در Kubernetes به‌طور پراکنده با تأخیر مواجه می‌شوند که نمی‌توان آن را با بارگذاری خود برنامه توضیح داد.

اساساً، برنامه‌ها تأخیر شبکه تصادفی تا 100 میلی‌ثانیه یا بیشتر را تجربه می‌کنند که منجر به وقفه یا تلاش مجدد می‌شود. انتظار می رفت که سرویس ها بتوانند به درخواست ها سریعتر از 100 میلی ثانیه پاسخ دهند. اما این غیرممکن است اگر خود اتصال زمان زیادی را صرف کند. به طور جداگانه، ما جستارهای بسیار سریع MySQL را مشاهده کردیم که باید میلی ثانیه طول بکشد، و MySQL در میلی ثانیه تکمیل شد، اما از منظر برنامه درخواست کننده، پاسخ 100 میلی ثانیه یا بیشتر طول کشید.

بلافاصله مشخص شد که مشکل فقط هنگام اتصال به گره Kubernetes رخ داده است، حتی اگر تماس از خارج از Kubernetes باشد. ساده ترین راه برای بازتولید مشکل در آزمایش است گیاهی، که از هر میزبان داخلی اجرا می شود، سرویس Kubernetes را روی یک پورت خاص آزمایش می کند و به طور پراکنده تاخیر بالایی را ثبت می کند. در این مقاله به این خواهیم پرداخت که چگونه توانستیم علت این مشکل را ردیابی کنیم.

حذف پیچیدگی های غیر ضروری در زنجیره منجر به شکست

با بازتولید همین مثال، می‌خواهیم تمرکز مشکل را محدود کنیم و لایه‌های غیرضروری از پیچیدگی را حذف کنیم. در ابتدا، عناصر زیادی در جریان بین Vegeta و غلاف های Kubernetes وجود داشت. برای شناسایی یک مشکل شبکه عمیق تر، باید برخی از آنها را رد کنید.

کلاینت (Vegeta) یک اتصال TCP با هر گره ای در خوشه ایجاد می کند. Kubernetes به عنوان یک شبکه همپوشانی (در بالای شبکه مرکز داده موجود) عمل می کند که از آن استفاده می کند IPIPیعنی بسته های IP شبکه همپوشانی را در داخل بسته های IP مرکز داده کپسوله می کند. هنگام اتصال به اولین گره، ترجمه آدرس شبکه انجام می شود ترجمه آدرس شبکه (NAT) حالتی برای ترجمه آدرس IP و پورت گره Kubernetes به آدرس IP و پورت در شبکه همپوشانی (به طور خاص، غلاف با برنامه). برای بسته های ورودی، دنباله معکوس اقدامات انجام می شود. این یک سیستم پیچیده با حالت های زیاد و عناصر بسیاری است که با استقرار و جابجایی سرویس ها دائماً به روز می شوند و تغییر می کنند.

سودمندی tcpdump در تست Vegeta در هنگام دست دادن TCP (بین SYN و SYN-ACK) تاخیر وجود دارد. برای حذف این پیچیدگی غیر ضروری، می توانید استفاده کنید hping3 برای "پینگ" های ساده با بسته های SYN. بررسی می کنیم که آیا تاخیری در بسته پاسخ وجود دارد یا خیر، و سپس اتصال را بازنشانی می کنیم. ما می‌توانیم داده‌ها را طوری فیلتر کنیم که فقط بسته‌های بزرگ‌تر از 100 میلی‌ثانیه را شامل شود و راه آسان‌تری برای بازتولید مشکل نسبت به آزمایش لایه 7 شبکه کامل Vegeta داشته باشیم. در اینجا "پینگ" های گره Kubernetes با استفاده از TCP SYN/SYN-ACK در سرویس "node port" (30927) در فواصل 10 میلی ثانیه، فیلتر شده توسط کندترین پاسخ ها آمده است:

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms

می تواند بلافاصله اولین مشاهده را انجام دهد. با قضاوت بر اساس اعداد ترتیبی و زمان‌بندی، واضح است که این تراکم‌های یک‌باره نیستند. تأخیر اغلب انباشته می شود و در نهایت پردازش می شود.

در مرحله بعد، ما می خواهیم دریابیم که کدام اجزا ممکن است در بروز تراکم دخیل باشند. شاید اینها برخی از صدها قانون iptables در NAT باشند؟ یا مشکلی در تونل IPIP در شبکه وجود دارد؟ یکی از راه‌های بررسی این موضوع، آزمایش هر مرحله از سیستم با حذف آن است. اگر NAT و منطق فایروال را حذف کنید و فقط قسمت IPIP را باقی بگذارید چه اتفاقی می افتد:

خوشبختانه، لینوکس دسترسی مستقیم به لایه پوشش IP را در صورتی که دستگاه در همان شبکه باشد آسان می کند:

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms

با قضاوت بر اساس نتایج، مشکل همچنان باقی است! این شامل iptables و NAT نمی شود. پس مشکل از TCP است؟ بیایید ببینیم یک پینگ معمولی ICMP چگونه پیش می رود:

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms

len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms

len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms

len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms

len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms

len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms

len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms

len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms

len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms

len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms

نتایج نشان می دهد که مشکل برطرف نشده است. شاید این یک تونل IPIP باشد؟ بیایید تست را بیشتر ساده کنیم:

آیا همه بسته ها بین این دو میزبان ارسال می شوند؟

theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms

len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms

len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms

len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms

len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms

len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms

ما وضعیت را به دو گره Kubernetes ساده کرده ایم که هر بسته، حتی یک پینگ ICMP را برای یکدیگر ارسال می کنند. اگر میزبان هدف "بد" باشد (بعضی بدتر از بقیه) آنها همچنان تأخیر را می بینند.

اکنون آخرین سوال: چرا تاخیر فقط در سرورهای kube-node رخ می دهد؟ و آیا زمانی که kube-node فرستنده یا گیرنده باشد این اتفاق می افتد؟ خوشبختانه، با ارسال یک بسته از میزبانی خارج از Kubernetes، اما با همان گیرنده "بد شناخته شده"، فهمیدن این موضوع نیز بسیار آسان است. همانطور که می بینید، مشکل ناپدید نشده است:

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms

سپس همان درخواست‌ها را از منبع قبلی kube-node به میزبان خارجی اجرا می‌کنیم (که میزبان منبع را حذف می‌کند زیرا پینگ شامل هر دو جزء RX و TX می‌شود):

theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
^C
--- 172.16.33.44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms

با بررسی بسته‌های تأخیر، اطلاعات بیشتری به دست آوردیم. به طور خاص، اینکه فرستنده (پایین) این وقفه را می بیند، اما گیرنده (بالا) نمی بیند - ستون Delta را (در چند ثانیه) ببینید:

علاوه بر این، اگر به تفاوت ترتیب بسته‌های TCP و ICMP (براساس اعداد ترتیبی) در سمت گیرنده نگاه کنید، بسته‌های ICMP همیشه به همان ترتیبی که ارسال شده‌اند، اما با زمان‌بندی متفاوت می‌رسند. در همان زمان، بسته های TCP گاهی اوقات به هم متصل می شوند و برخی از آنها گیر می کنند. به طور خاص، اگر پورت های بسته های SYN را بررسی کنید، آنها در سمت فرستنده به ترتیب هستند، اما در سمت گیرنده نیستند.

یک تفاوت ظریف در نحوه وجود دارد کارت های شبکه سرورهای مدرن (مانند سرورهای مرکز داده ما) بسته های حاوی TCP یا ICMP را پردازش می کنند. هنگامی که بسته ای وارد می شود، آداپتور شبکه آن را در هر اتصال هش می کند، یعنی سعی می کند اتصالات را به صف شکسته و هر صف را به یک هسته پردازشگر جداگانه بفرستد. برای TCP، این هش شامل آدرس IP و پورت منبع و مقصد است. به عبارت دیگر، هر اتصال (به طور بالقوه) متفاوت هش می شود. برای ICMP، فقط آدرس های IP هش می شوند، زیرا هیچ پورتی وجود ندارد.

مشاهدات جدید دیگر: در این دوره شاهد تاخیرهای ICMP در تمام ارتباطات بین دو میزبان هستیم، اما TCP اینطور نیست. این به ما می‌گوید که علت احتمالاً مربوط به هش کردن صف RX است: ازدحام تقریباً به طور قطع در پردازش بسته‌های RX است، نه در ارسال پاسخ‌ها.

این کار ارسال بسته ها را از لیست علل احتمالی حذف می کند. اکنون می دانیم که مشکل پردازش بسته در سمت دریافت در برخی از سرورهای گره کوبه است.

درک پردازش بسته در هسته لینوکس

برای درک اینکه چرا این مشکل در گیرنده برخی از سرورهای نود kube رخ می دهد، بیایید به نحوه پردازش بسته ها توسط هسته لینوکس نگاه کنیم.

با بازگشت به ساده ترین پیاده سازی سنتی، کارت شبکه بسته را دریافت و ارسال می کند قطع کردن هسته لینوکس که بسته ای وجود دارد که باید پردازش شود. هسته کار دیگر را متوقف می کند، زمینه را به کنترل کننده وقفه تغییر می دهد، بسته را پردازش می کند و سپس به وظایف فعلی باز می گردد.

این تغییر زمینه آهسته است: ممکن است تاخیر در کارت های شبکه 10 مگابیت در ثانیه در دهه 90 قابل توجه نباشد، اما در کارت های مدرن 10G با حداکثر توان عملیاتی 15 میلیون بسته در ثانیه، هر هسته یک سرور کوچک هشت هسته ای می تواند میلیون ها وقفه داشته باشد. بار در ثانیه

برای اینکه دائماً وقفه ها را مدیریت نکنید، سال ها پیش لینوکس اضافه کرد NAPI: شبکه API که همه درایورهای مدرن از آن برای بهبود عملکرد در سرعت های بالا استفاده می کنند. در سرعت های پایین، هسته همچنان وقفه هایی را از کارت شبکه به روش قدیمی دریافت می کند. هنگامی که بسته های کافی وارد می شوند که از آستانه فراتر می روند، هسته وقفه ها را غیرفعال می کند و در عوض شروع به نظرسنجی از آداپتور شبکه و جمع آوری بسته ها به صورت تکه ای می کند. پردازش در softirq انجام می شود، یعنی در زمینه نرم افزار قطع می شود پس از تماس های سیستمی و وقفه های سخت افزاری، زمانی که هسته (بر خلاف فضای کاربر) در حال اجرا است.

این بسیار سریعتر است، اما باعث یک مشکل متفاوت می شود. اگر بسته‌ها بیش از حد وجود داشته باشد، تمام زمان صرف پردازش بسته‌ها از کارت شبکه می‌شود و فرآیندهای فضای کاربر زمانی برای خالی کردن واقعی این صف‌ها (خواندن از اتصالات TCP و غیره) ندارند. در نهایت صف ها پر می شود و ما شروع به انداختن بسته ها می کنیم. در تلاش برای یافتن تعادل، هسته بودجه ای برای حداکثر تعداد بسته های پردازش شده در زمینه softirq تعیین می کند. هنگامی که از این بودجه تجاوز می شود، یک موضوع جداگانه بیدار می شود ksoftirqd (یکی از آنها را در آن خواهید دید ps در هر هسته) که این نرم افزارها را خارج از مسیر معمولی syscall/interrupt کنترل می کند. این موضوع با استفاده از زمان‌بندی فرآیند استاندارد، که تلاش می‌کند منابع را به طور عادلانه تخصیص دهد، برنامه‌ریزی می‌شود.

با مطالعه نحوه پردازش هسته بسته ها، می توانید ببینید که احتمال احتقان خاصی وجود دارد. اگر تماس‌های softirq کمتر دریافت می‌شوند، بسته‌ها باید مدتی منتظر بمانند تا در صف RX روی کارت شبکه پردازش شوند. این ممکن است به دلیل برخی کارها باشد که هسته پردازنده را مسدود می کند، یا چیز دیگری مانع از اجرای softirq توسط هسته می شود.

محدود کردن پردازش به هسته یا روش

تأخیرهای Softirq در حال حاضر فقط یک حدس است. اما منطقی است، و ما می دانیم که چیزی بسیار مشابه را می بینیم. بنابراین قدم بعدی تایید این نظریه است. و اگر تایید شد دلیل تاخیر را پیدا کنید.

بیایید به بسته های آهسته خود برگردیم:

len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms

len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms

len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms

len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms

len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms

len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms

len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms

len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms

همانطور که قبلاً بحث شد، این بسته های ICMP در یک صف واحد RX NIC هش شده و توسط یک هسته CPU پردازش می شوند. اگر بخواهیم بفهمیم لینوکس چگونه کار می‌کند، بهتر است بدانیم این بسته‌ها در کجا (بر روی کدام هسته CPU) و چگونه (softirq، ksoftirqd) پردازش می‌شوند تا فرآیند را ردیابی کنیم.

اکنون زمان استفاده از ابزارهایی است که به شما امکان نظارت بر هسته لینوکس را در زمان واقعی می دهد. در اینجا ما استفاده کردیم BCC. این مجموعه از ابزارها به شما امکان می دهد برنامه های کوچک C بنویسید که توابع دلخواه را در هسته قلاب کرده و رویدادها را در یک برنامه پایتون فضای کاربر بافر می کند که می تواند آنها را پردازش کند و نتیجه را به شما برگرداند. قلاب کردن توابع دلخواه در هسته یک موضوع پیچیده است، اما این ابزار برای حداکثر امنیت طراحی شده است و برای ردیابی دقیقاً انواع مسائل تولیدی طراحی شده است که به راحتی در یک محیط آزمایش یا توسعه بازتولید نمی شوند.

طرح در اینجا ساده است: ما می دانیم که هسته این پینگ های ICMP را پردازش می کند، بنابراین یک قلاب روی تابع هسته قرار می دهیم. icmp_echo، که بسته درخواست اکو ICMP ورودی را می پذیرد و شروع به ارسال پاسخ اکو ICMP می کند. ما می توانیم بسته را با افزایش عدد icmp_seq شناسایی کنیم که نشان می دهد hping3 بالاتر

رمز اسکریپت bcc پیچیده به نظر می رسد، اما آنقدرها هم که به نظر می رسد ترسناک نیست. تابع icmp_echo انتقال می دهد struct sk_buff *skb: این یک بسته با "درخواست اکو" است. ما می توانیم آن را دنبال کنیم، دنباله را بیرون بکشیم echo.sequence (که با icmp_seq توسط hping3 выше) و آن را به فضای کاربری ارسال کنید. همچنین گرفتن نام/شناسه فرآیند فعلی راحت است. در زیر نتایجی وجود دارد که ما مستقیماً در هنگام پردازش بسته‌ها توسط هسته مشاهده می‌کنیم:

نام فرآیند TGID PID 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 swapper/20041 20086 775 0 0 11 776 مبادله/0 0 11 777 swapper/0 0 11 778 spokes-report-s 4512

در اینجا لازم به ذکر است که در زمینه softirq فرآیندهایی که فراخوانی های سیستمی را انجام می دهند به عنوان "فرایندها" ظاهر می شوند در حالی که در واقع این هسته است که بسته ها را به طور ایمن در زمینه هسته پردازش می کند.

با این ابزار می‌توانیم فرآیندهای خاص را با بسته‌های خاصی که تأخیر را نشان می‌دهند مرتبط کنیم hping3. بیایید آن را ساده کنیم grep در این گرفتن برای مقادیر خاص icmp_seq. بسته های مطابق با مقادیر icmp_seq بالا همراه با RTT آنها که در بالا مشاهده کردیم ذکر شده است (در داخل پرانتز مقادیر RTT مورد انتظار برای بسته هایی که به دلیل مقادیر RTT کمتر از 50 میلی ثانیه فیلتر کرده بودیم آمده است):

نام فرآیند TGID PID ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftirq ** 11ms 1954 89 ksoftirq* 76 ** 76ms 11 1955 ksoftirqd/79 76 ** 76ms 11 1956 ksoftirqd/69 76 ** 76ms 11 1957 ksoftirqd/59 76 ** (76ms) 11 1958 ksoftirqd/49 76 ** (76ms) 11 ** 1959 ksoftirqd 39 **76 ksoftirqd 76 11 ksoftirqd 1960 29 ksoftirqd/76 / 76 11 ** (1961ms) 19 76 ksoftirqd/76 11 ** (1962ms) -- 9 10137 cadvisor 10436 2068 10137 cadvisor 10436 2069 76 76 ksoftirqd/11ir 2070 ksoftirqd/75ir 76 ** 76 ms 11 2071 ksoftirqd/ 65 76 ** 76ms 11 2072 ksoftirqd/55 76 ** (76ms) 11 2073 ksoftirqd/45 76 ** (76ms) 11 2074 ksoftirqd/35 76 **76 (11ms 2075 ksoftirqd) ) 25 76 ksoftirqd/76 11 ** (2076 میلی‌ثانیه)

نتایج چندین چیز را به ما می گوید. اولا، تمام این بسته ها توسط زمینه پردازش می شوند ksoftirqd/11. این بدان معناست که برای این جفت ماشین خاص، بسته‌های ICMP به هسته 11 در انتهای دریافت هش می‌شوند. همچنین می بینیم که هر زمان جم باشد، بسته هایی وجود دارند که در متن فراخوانی سیستم پردازش می شوند cadvisor. سپس ksoftirqd وظیفه را بر عهده می گیرد و صف انباشته را پردازش می کند: دقیقاً تعداد بسته هایی که پس از آن انباشته شده اند. cadvisor.

این واقعیت که بلافاصله قبل از آن همیشه کار می کند cadvisor، دلالت بر دخالت او در مشکل دارد. از قضا، هدف cadvisor - "تجزیه و تحلیل استفاده از منابع و ویژگی های عملکرد کانتینرهای در حال اجرا" به جای ایجاد این مشکل عملکرد.

مانند سایر جنبه‌های کانتینرها، اینها همگی ابزارهای بسیار پیشرفته‌ای هستند و می‌توان انتظار داشت که در برخی شرایط پیش‌بینی نشده مشکلات عملکردی را تجربه کنند.

cadvisor چه کاری انجام می دهد که صف بسته را کند می کند؟

ما اکنون درک بسیار خوبی از چگونگی وقوع خرابی، فرآیند ایجاد آن و روی کدام CPU داریم. می بینیم که به دلیل مسدود شدن سخت، هسته لینوکس زمانی برای برنامه ریزی ندارد ksoftirqd. و می بینیم که بسته ها در متن پردازش می شوند cadvisor. منطقی است که چنین فرض کنیم cadvisor یک syscall آهسته راه اندازی می کند، پس از آن تمام بسته های انباشته شده در آن زمان پردازش می شوند:

این یک نظریه است، اما چگونه آن را آزمایش کنیم؟ کاری که ما می‌توانیم انجام دهیم این است که هسته CPU را در طول این فرآیند ردیابی کنیم، نقطه‌ای را پیدا کنیم که تعداد بسته‌ها از بودجه فراتر می‌رود و ksoftirqd فراخوانی می‌شود، و سپس کمی به عقب‌تر نگاه کنیم تا ببینیم دقیقاً قبل از آن نقطه دقیقاً چه چیزی روی هسته CPU اجرا می‌شده است. . مثل این است که هر چند میلی ثانیه یک بار از CPU اشعه ایکس می گیریم. چیزی شبیه به این خواهد بود:

به راحتی، همه اینها را می توان با ابزارهای موجود انجام داد. مثلا، رکورد پرف هسته CPU داده شده را در یک فرکانس مشخص بررسی می کند و می تواند برنامه ای از تماس ها را با سیستم در حال اجرا، شامل فضای کاربر و هسته لینوکس ایجاد کند. می توانید این رکورد را بگیرید و با استفاده از یک فورک کوچک برنامه پردازش کنید شعله گراف از برندان گرگ، که ترتیب ردیابی پشته را حفظ می کند. ما می‌توانیم ردیابی‌های پشته‌ای تک خطی را هر ۱ میلی‌ثانیه ذخیره کنیم، و سپس ۱۰۰ میلی‌ثانیه قبل از نمایش ردیابی، نمونه‌ای را برجسته و ذخیره کنیم. ksoftirqd:

# record 999 times a second, or every 1ms with some offset so not to align exactly with timers
sudo perf record -C 11 -g -F 999
# take that recording and make a simpler stack trace.
sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100

در اینجا نتایج آمده است:

(сотни следов, которые выглядят похожими)

cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_run

در اینجا چیزهای زیادی وجود دارد، اما نکته اصلی این است که ما الگوی "cadvisor before ksoftirqd" را که قبلاً در ردیاب ICMP دیدیم، پیدا می کنیم. چه مفهومی داره؟

هر خط یک ردیابی CPU در یک نقطه خاص از زمان است. هر فراخوانی پشته در یک خط با یک نقطه ویرگول از هم جدا می شود. در وسط خطوط می بینیم که syscall فراخوانی می شود: read(): .... ;do_syscall_64;sys_read; .... بنابراین cadvisor زمان زیادی را صرف تماس سیستمی می کند read()مربوط به توابع mem_cgroup_* (بالای پشته تماس/پایان خط).

دیدن اینکه در ردیابی تماس دقیقاً چه چیزی خوانده می شود ناخوشایند است، پس بیایید اجرا کنیم strace و بیایید ببینیم cadvisor چه کاری انجام می دهد و تماس های سیستمی بیش از 100 میلی ثانیه را پیدا کنیم:

theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] <... futex resumed> ) = 0 <0.156784>
[pid 10432] <... futex resumed> ) = 0 <0.258285>
[pid 10137] <... futex resumed> ) = 0 <0.678382>
[pid 10384] <... futex resumed> ) = 0 <0.762328>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 658 <0.179438>
[pid 10384] <... futex resumed> ) = 0 <0.104614>
[pid 10436] <... futex resumed> ) = 0 <0.175936>
[pid 10436] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.228091>
[pid 10427] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.207334>
[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>
[pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 660 <0.159891>
[pid 10417] <... futex resumed> ) = 0 <0.917495>
[pid 10436] <... futex resumed> ) = 0 <0.208172>
[pid 10417] <... futex resumed> ) = 0 <0.190763>
[pid 10417] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576 <0.154442>

همانطور که انتظار دارید، ما در اینجا شاهد تماس های کند هستیم read(). از محتویات عملیات خواندن و زمینه mem_cgroup واضح است که این چالش ها read() به فایل مراجعه کنید memory.stat، که میزان استفاده از حافظه و محدودیت های cgroup را نشان می دهد (فناوری جداسازی منابع Docker). ابزار cadvisor این فایل را جستجو می کند تا اطلاعات استفاده از منابع را برای کانتینرها به دست آورد. بیایید بررسی کنیم که آیا هسته یا cadvisor کار غیرمنتظره ای انجام می دهد:

theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null

real 0m0.153s
user 0m0.000s
sys 0m0.152s
theojulienne@kube-node-bad ~ $

اکنون می‌توانیم باگ را بازتولید کنیم و بفهمیم که هسته لینوکس با آسیب‌شناسی مواجه است.

چرا عملیات خواندن اینقدر کند است؟

در این مرحله، یافتن پیام های سایر کاربران در مورد مشکلات مشابه بسیار آسان تر است. همانطور که مشخص شد، در ردیاب cadvisor این باگ به عنوان گزارش شده است مشکل استفاده بیش از حد از CPU، فقط هیچ کس متوجه نشد که تأخیر نیز به طور تصادفی در پشته شبکه منعکس می شود. در واقع مشاهده شد که cadvisor بیش از حد انتظار زمان CPU را مصرف می کند، اما به این اهمیت چندانی داده نشد، زیرا سرورهای ما منابع CPU زیادی دارند، بنابراین مشکل به دقت مورد مطالعه قرار نگرفت.

مشکل این است که cgroup ها استفاده از حافظه را در فضای نام (کانتینر) در نظر می گیرند. هنگامی که تمام فرآیندهای این cgroup خارج می شوند، Docker cgroup حافظه را آزاد می کند. با این حال، "حافظه" فقط حافظه پردازشی نیست. اگرچه خود حافظه پردازشی دیگر مورد استفاده قرار نمی گیرد، به نظر می رسد که هسته همچنان محتویات کش شده، مانند دندانه ها و inode ها (فراداده دایرکتوری و فایل) را که در cgroup حافظه ذخیره می شوند، اختصاص می دهد. از توضیحات مشکل:

zombie cgroups: cgroup هایی که هیچ پردازشی ندارند و حذف شده اند، اما همچنان حافظه تخصیص یافته دارند (در مورد من، از حافظه نهان دندانی، اما می توان آن را از کش صفحه یا tmpfs نیز تخصیص داد).

بررسی هسته تمام صفحات در حافظه پنهان هنگام آزاد کردن یک cgroup می‌تواند بسیار کند باشد، بنابراین فرآیند تنبل انتخاب می‌شود: منتظر بمانید تا این صفحات دوباره درخواست شوند، و سپس در نهایت cgroup را هنگامی که واقعاً به حافظه نیاز است پاک کنید. تا این مرحله، cgroup همچنان هنگام جمع آوری آمار در نظر گرفته می شود.

از نقطه نظر عملکرد، آنها حافظه را قربانی عملکرد کردند: سرعت بخشیدن به پاکسازی اولیه با باقی گذاشتن مقداری حافظه پنهان. این خوبه. هنگامی که هسته از آخرین حافظه کش استفاده می کند، cgroup در نهایت پاک می شود، بنابراین نمی توان آن را "نشت" نامید. متأسفانه، اجرای خاص مکانیسم جستجو memory.stat در این نسخه هسته (4.9)، همراه با حجم عظیمی از حافظه در سرورهای ما، به این معنی است که بازیابی آخرین داده‌های کش شده و پاک کردن زامبی‌های cgroup بسیار بیشتر طول می‌کشد.

به نظر می رسد که برخی از گره های ما آنقدر زامبی cgroup داشتند که خواندن و تأخیر بیش از یک ثانیه بود.

راه‌حل مشکل cadvisor آزاد کردن فوری کش‌های دندانه‌ای/inode در سراسر سیستم است، که فوراً تأخیر خواندن و همچنین تأخیر شبکه را در میزبان حذف می‌کند، زیرا پاک کردن کش، صفحات cgroup زامبی‌های کش شده را روشن می‌کند و آنها را نیز آزاد می‌کند. این یک راه حل نیست، اما علت مشکل را تایید می کند.

مشخص شد که در نسخه‌های هسته جدیدتر (4.19+) عملکرد تماس بهبود یافته است memory.stat، بنابراین تغییر به این هسته مشکل را برطرف کرد. در همان زمان، ابزارهایی برای شناسایی گره‌های مشکل‌ساز در خوشه‌های Kubernetes، تخلیه و راه‌اندازی مجدد آن‌ها داشتیم. ما همه خوشه ها را شانه زدیم، گره هایی با تأخیر کافی بالا پیدا کردیم و آنها را راه اندازی مجدد کردیم. این به ما زمان داد تا سیستم عامل را در سرورهای باقی مانده به روز کنیم.

مجموع

از آنجایی که این باگ پردازش صف RX NIC را برای صدها میلی ثانیه متوقف کرد، به طور همزمان باعث تأخیر زیاد در اتصالات کوتاه و تأخیر میانی اتصال، مانند بین درخواست‌های MySQL و بسته‌های پاسخ می‌شود.

درک و حفظ عملکرد اساسی ترین سیستم ها، مانند Kubernetes، برای قابلیت اطمینان و سرعت تمام خدمات مبتنی بر آنها بسیار مهم است. هر سیستمی که اجرا می کنید از بهبود عملکرد Kubernetes سود می برد.

منبع: www.habr.com