לפני כמה שנים Kubernetes כבר דנו בבלוג הרשמי של GitHub. מאז, היא הפכה לטכנולוגיה הסטנדרטית לפריסת שירותים. Kubernetes מנהלת כעת חלק ניכר מהשירותים הפנימיים והציבוריים. ככל שהאשכולות שלנו גדלו ודרישות הביצועים הפכו מחמירות יותר, התחלנו לשים לב שחלק מהשירותים ב-Kubernetes חווים חביון באופן ספורדי שלא ניתן היה להסביר על ידי העומס של האפליקציה עצמה.

בעיקרו של דבר, יישומים חווים השהיית רשת אקראית של עד 100 אלפיות השנייה או יותר, וכתוצאה מכך לפסקי זמן או ניסיונות חוזרים. השירותים היו אמורים להיות מסוגלים להגיב לבקשות הרבה יותר מהר מ-100 אלפיות השנייה. אבל זה בלתי אפשרי אם החיבור עצמו לוקח כל כך הרבה זמן. בנפרד, צפינו בשאילתות MySQL מהירות מאוד שאמורות לקחת אלפיות שניות, ו-MySQL אכן הושלמה באלפיות שניות, אבל מנקודת המבט של האפליקציה המבקשת, התגובה ארכה 100 אלפיות השנייה או יותר.

מיד התברר שהבעיה התרחשה רק בחיבור לצומת Kubernetes, גם אם השיחה הגיעה מחוץ ל-Kubernetes. הדרך הקלה ביותר לשחזר את הבעיה היא בבדיקה לִחיוֹת חַיִים רֵיקִים, הפועל מכל מארח פנימי, בודק את שירות Kubernetes ביציאה ספציפית, ורושם באופן ספורדי זמן השהייה גבוה. במאמר זה, נבחן כיצד הצלחנו לאתר את הגורם לבעיה זו.

ביטול מורכבות מיותרת בשרשרת המובילה לכישלון

על ידי שחזור אותה דוגמה, רצינו לצמצם את מוקד הבעיה ולהסיר שכבות מיותרות של מורכבות. בתחילה, היו יותר מדי אלמנטים בזרימה בין Vegeta לתרמילים של Kubernetes. כדי לזהות בעיית רשת עמוקה יותר, עליך לשלול חלק מהן.

הלקוח (Vegeta) יוצר חיבור TCP עם כל צומת באשכול. Kubernetes פועלת כרשת שכבת-על (על גבי רשת מרכז הנתונים הקיימת) המשתמשת IPIP, כלומר, הוא עוטף את מנות ה-IP של רשת השכבה בתוך מנות ה-IP של מרכז הנתונים. בעת חיבור לצומת הראשון, מתבצע תרגום כתובת רשת תרגום כתובת רשת (NAT) stateful כדי לתרגם את כתובת ה-IP והיציאה של צומת Kubernetes לכתובת ה-IP וליציאה ברשת שכבת-העל (באופן ספציפי, הפוד עם האפליקציה). עבור מנות נכנסות, מתבצע רצף הפוך של פעולות. זוהי מערכת מורכבת עם הרבה מצב ואלמנטים רבים שמתעדכנים ומשתנים כל הזמן עם פריסת השירותים והזזתם.

שירות tcpdump במבחן Vegeta יש עיכוב במהלך לחיצת היד של TCP (בין SYN ל-SYN-ACK). כדי להסיר את המורכבות המיותרת הזו, אתה יכול להשתמש hping3 עבור "פינגים" פשוטים עם מנות SYN. אנו בודקים אם יש עיכוב בחבילת התגובה, ולאחר מכן מאפסים את החיבור. אנחנו יכולים לסנן את הנתונים כך שיכללו רק מנות גדולות מ-100 אלפיות השנייה ולקבל דרך קלה יותר לשחזר את הבעיה מאשר מבחן שכבה 7 של הרשת המלאה של Vegeta. להלן "פינגים" של צומת Kubernetes באמצעות TCP SYN/SYN-ACK ב"יציאת הצומת" של השירות (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

על ידי בחינת לכידת מנות חביון, השגנו מידע נוסף. ספציפית, שהשולח (למטה) רואה את הזמן הקצוב הזה, אבל הנמען (למעלה) לא - ראה את העמודה דלתא (בשניות):

בנוסף, אם מסתכלים על ההבדל בסדר מנות TCP ו-ICMP (לפי מספרי רצף) בצד הנמען, מנות ICMP מגיעות תמיד באותו רצף שבו הן נשלחו, אך בתזמון שונה. יחד עם זאת, מנות TCP לפעמים משתלבות, וחלקן נתקעות. בפרט, אם בוחנים את היציאות של מנות SYN, הן מסודרות בצד השולח, אבל לא בצד של המקלט.

יש הבדל דק באיך כרטיסי רשת שרתים מודרניים (כמו אלו במרכז הנתונים שלנו) מעבדים מנות המכילות TCP או ICMP. כאשר מגיעה חבילה, מתאם הרשת "מגיב אותה לכל חיבור", כלומר מנסה לפרק את החיבורים לתורים ולשלוח כל תור לליבה נפרדת של מעבד. עבור TCP, Hash זה כולל גם את כתובת ה-IP והיציאה של המקור וגם היעד. במילים אחרות, כל חיבור גיבוב (פוטנציאלי) בצורה שונה. עבור ICMP, רק כתובות IP עוברות גיבוב, מכיוון שאין יציאות.

עוד תצפית חדשה: במהלך תקופה זו אנו רואים עיכובים של ICMP בכל התקשורת בין שני מארחים, אך TCP לא. זה אומר לנו שהסיבה כנראה קשורה לגיבוב של תור RX: העומס הוא כמעט בוודאות בעיבוד מנות RX, לא בשליחת תגובות.

זה מבטל שליחת מנות מרשימת הסיבות האפשריות. כעת אנו יודעים שבעיית עיבוד המנות נמצאת בצד הקבלה בכמה שרתי kube-node.

הבנת עיבוד מנות בליבת לינוקס

כדי להבין מדוע הבעיה מתרחשת במקלט בכמה שרתי kube-node, הבה נבחן כיצד ליבת לינוקס מעבדת מנות.

אם נחזור למימוש המסורתי הפשוט ביותר, כרטיס הרשת מקבל את החבילה ושולח פסיקת ליבת לינוקס שיש חבילה שצריך לעבד. הקרנל מפסיק עבודה אחרת, מחליף את ההקשר למטפל בפסיקות, מעבד את החבילה ואז חוזר למשימות הנוכחיות.

מיתוג ההקשר הזה איטי: ייתכן שהשהייה לא הייתה מורגשת בכרטיסי רשת של 10Mbps בשנות ה-90, אבל בכרטיסי 10G מודרניים עם תפוקה מקסימלית של 15 מיליון חבילות בשנייה, כל ליבה של שרת שמונה ליבות קטן יכולה להיקטע במיליוני של פעמים בשנייה.

כדי לא לטפל כל הזמן בהפרעות, לפני שנים רבות נוספה לינוקס NAPI: רשת API שכל הדרייברים המודרניים משתמשים בו כדי לשפר ביצועים במהירויות גבוהות. במהירויות נמוכות הקרנל עדיין מקבל פסיקות מכרטיס הרשת בדרך הישנה. ברגע שמגיעות מספיק מנות החורגות מהסף, הקרנל משבית את ההפרעות ובמקום זאת מתחיל לבצע סקר למתאם הרשת ולאסוף מנות בחתיכות. העיבוד מתבצע ב-softirq, כלומר ב הקשר של הפרעות בתוכנה לאחר קריאות מערכת והפרעות בחומרה, כאשר הקרנל (בניגוד למרחב המשתמש) כבר פועל.

זה הרבה יותר מהיר, אבל גורם לבעיה אחרת. אם יש יותר מדי מנות, אז כל הזמן מוקדש לעיבוד מנות מכרטיס הרשת, ולתהליכי שטח המשתמש אין זמן לרוקן את התורים האלה בפועל (קריאה מחיבורי TCP וכו'). בסופו של דבר התורים מתמלאים ואנחנו מתחילים להוריד מנות. בניסיון למצוא איזון, הקרנל מגדיר תקציב למספר המרבי של מנות המעובדות בהקשר softirq. לאחר חריגה מהתקציב הזה, מתעורר שרשור נפרד ksoftirqd (תראה אחד מהם ב ps לכל ליבה) המטפל ב-softirqs אלה מחוץ לנתיב ה-syscall/הפסקה הרגיל. השרשור הזה מתוזמן באמצעות מתזמן התהליך הסטנדרטי, שמנסה להקצות משאבים בצורה הוגנת.

לאחר שלמדת כיצד הקרנל מעבד מנות, אתה יכול לראות שיש סבירות מסוימת לעומס. אם שיחות 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 יחיד ומעובדות על ידי ליבת מעבד יחידה. אם אנחנו רוצים להבין איך לינוקס עובדת, כדאי לדעת היכן (על איזו ליבת מעבד) וכיצד (softirq, ksoftirqd) עיבוד החבילות הללו על מנת לעקוב אחר התהליך.

עכשיו הגיע הזמן להשתמש בכלים המאפשרים לך לפקח על ליבת לינוקס בזמן אמת. כאן השתמשנו BCC. סט כלים זה מאפשר לך לכתוב תוכניות C קטנות המחברים פונקציות שרירותיות בקרנל ומחצצות את האירועים לתוכנת Python במרחב המשתמש שיכולה לעבד אותם ולהחזיר לך את התוצאה. חיבור פונקציות שרירותיות בקרנל הוא עניין מורכב, אבל הכלי מיועד לאבטחה מירבית ונועד לאתר בדיוק את סוג בעיות הייצור שלא ניתן לשחזר בקלות בסביבת בדיקה או פיתוח.

התוכנית כאן היא פשוטה: אנחנו יודעים שהקרנל מעבד את הפינגים האלה של ICMP, אז אנחנו נחבר את פונקציית הקרנל icmp_echo, המקבל חבילת בקשת הד נכנסת של ICMP ומתחיל שליחת תגובת הד של ICMP. נוכל לזהות חבילה על ידי הגדלת המספר icmp_seq, שמופיע hping3 גבוה יותר.

קוד סקריפט מוסתר נראה מסובך, אבל זה לא מפחיד כמו שזה נראה. פוּנקצִיָה icmp_echo משדר struct sk_buff *skb: זוהי חבילה עם "בקשת הד". אנחנו יכולים לעקוב אחרי זה, להוציא את הרצף echo.sequence (מה שמשוווה עם icmp_seq על ידי hping3 выше), ושלח אותו למרחב המשתמש. זה גם נוח ללכוד את שם התהליך הנוכחי/מזהה. להלן התוצאות שאנו רואים ישירות בזמן שהקרנל מעבד מנות:

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 prometheus/775 0 swapper 0 11 776 0 0 החלפה/11 777 0 0 דוחות חישורים 11

יש לציין כאן כי בהקשר softirq תהליכים שביצעו קריאות למערכת יופיעו כ"תהליכים" כאשר למעשה זה הקרנל שמעבד בבטחה מנות בהקשר של הקרנל.

עם הכלי הזה אנחנו יכולים לשייך תהליכים ספציפיים לחבילות ספציפיות שמראות עיכוב של hping3. בואו נעשה את זה פשוט grep על לכידה זו עבור ערכים מסוימים icmp_seq. מנות התואמות לערכי icmp_seq שלעיל צוינו יחד עם ה-RTT שלהם שצפינו למעלה (בסוגריים הם ערכי ה-RTT הצפויים לחבילות שסוננו עקב ערכי RTT של פחות מ-50 אלפיות השנייה):

TGID PID PROCESS NAME ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftir 11 1954 ksoftirq 89d d/76 76 ** 11ms 1955 79 ksoftirqd/ 76 76 ** 11ms 1956 69 ksoftirqd/76 76 ** 11ms 1957 59 ksoftirqd/76 76 ** (11ms) 1958 49 ksoftirqd/76 76 ** (11ms) 1959 39d softir 76 76d רך irqd/ 11 1960 ** (29ms) 76 76 ksoftirqd/11 1961 ** (19ms) -- 76 76 cadvisor 11 1962 9 cadvisor 10137 10436 2068 ksoftirq 10137 ksoftirq 10436k /2069 76 ** 76ms 11 2070 ksoftirqd/ 75 76 ** 76ms 11 2071 ksoftirqd/65 76 ** (76ms) 11 2072 ksoftirqd/55 76 ** (76ms) 11 2073 ksoftirqd/45 76 ** (76ms) ** (11qms) ) 2074 35 ksoftirqd/76 76 ** (11ms)

התוצאות מספרות לנו כמה דברים. ראשית, כל החבילות הללו מעובדות על ידי ההקשר ksoftirqd/11. משמעות הדבר היא שעבור צמד המכונות המסוים הזה, מנות ICMP הועברו לגיבוב לליבה 11 בקצה המקבל. אנו רואים גם שבכל פעם שיש ג'אם, יש מנות שמעובדות בהקשר של קריאת המערכת cadvisor. ואז ksoftirqd משתלט על המשימה ומעבד את התור המצטבר: בדיוק מספר החבילות שהצטבר לאחר מכן cadvisor.

העובדה שמיד לפני זה תמיד עובד cadvisor, מרמז על מעורבותו בבעיה. באופן אירוני, המטרה cadvisor - "נתח את מאפייני השימוש במשאבים וביצועים של מיכלים הפועלים" במקום לגרום לבעיית ביצועים זו.

כמו בהיבטים אחרים של קונטיינרים, כל אלה הם כלים מתקדמים ביותר וניתן לצפות שייתקלו בבעיות ביצועים בנסיבות בלתי צפויות.

מה עושה cadvisor שמאט את תור החבילות?

כעת יש לנו הבנה טובה למדי כיצד הקריסה מתרחשת, איזה תהליך גורם לה, ועל איזה מעבד. אנו רואים שבשל חסימה קשה, לקרנל הלינוקס אין זמן לתזמן ksoftirqd. ואנחנו רואים שמנות מעובדות בהקשר cadvisor. זה הגיוני להניח את זה cadvisor מפעיל מערכת הפעלה איטית, שלאחריה כל החבילות שנצברו באותו זמן מעובדות:

זו תיאוריה, אבל איך לבדוק אותה? מה שאנחנו יכולים לעשות זה לעקוב אחר ליבת ה-CPU לאורך התהליך הזה, למצוא את הנקודה שבה מספר החבילות עובר את התקציב ונקרא ksoftirqd, ואז להסתכל קצת יותר אחורה כדי לראות מה בדיוק רץ בליבת ה-CPU ממש לפני הנקודה הזו. . זה כמו צילום רנטגן של המעבד כל כמה אלפיות שניות. זה ייראה בערך כך:

בנוחות, כל זה יכול להיעשות עם כלים קיימים. לדוגמה, שיא מושלם בודק ליבת CPU נתונה בתדירות מוגדרת ויכול ליצור לוח זמנים של שיחות למערכת הפועלת, כולל שטח משתמש וגם ליבת לינוקס. אתה יכול לקחת את הרשומה הזו ולעבד אותה באמצעות מזלג קטן של התוכנית FlameGraph מ-Brendan Gregg, המשמר את סדר עקבות הערימה. אנו יכולים לשמור עקבות מחסנית בשורה אחת כל 1 ms, ולאחר מכן להדגיש ולשמור דגימה 100 אלפיות שניות לפני שהעקיבה פוגעת 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 tracer. מה זה אומר?

כל שורה היא עקבות 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 tracker דווח על הבאג הזה בעיה של שימוש מוגזם במעבד, רק שאף אחד לא שם לב שהשהייה משתקפת באופן אקראי בערימת הרשת. אכן הבחינו ש-cadvisor צורכת יותר זמן מעבד מהצפוי, אבל זה לא קיבל חשיבות רבה, מכיוון שלשרתים שלנו יש הרבה משאבי מעבד, כך שהבעיה לא נחקרה בקפידה.

הבעיה היא ש-cgroups לוקחות בחשבון שימוש בזיכרון בתוך מרחב השמות (מיכל). כאשר כל התהליכים ב-cgroup זו יוצאים, Docker משחרר את ה-cgroup של הזיכרון. עם זאת, "זיכרון" אינו רק זיכרון תהליך. למרות שזיכרון התהליך עצמו כבר לא בשימוש, נראה שהקרנל עדיין מקצה תוכן שמור, כגון דנטריות ואינודים (מטא-נתונים של ספריות וקבצים), שנשמרים במטמון ב-cgroup של הזיכרון. מתוך תיאור הבעיה:

zombie cgroups: cgroups שאין להם תהליכים ונמחקו, אבל עדיין מוקצה להם זיכרון (במקרה שלי, ממטמון dentry, אבל אפשר להקצות אותו גם ממטמון העמוד או tmpfs).

הבדיקה של הליבה של כל הדפים במטמון בעת ​​שחרור cgroup יכולה להיות מאוד איטית, ולכן התהליך העצל נבחר: המתן עד שהדפים הללו יתבקשו שוב, ולאחר מכן נקה לבסוף את cgroup כשיש צורך בזיכרון בפועל. עד לנקודה זו, cgroup עדיין נלקחת בחשבון בעת ​​איסוף נתונים סטטיסטיים.

מנקודת מבט של ביצועים, הם הקריבו זיכרון עבור ביצועים: האצת הניקוי הראשוני על ידי השארת זיכרון שמור מאחור. זה בסדר. כאשר הליבה משתמשת בזיכרון האחרון בזיכרון המטמון, ה-cgroup בסופו של דבר מנוקה, כך שלא ניתן לקרוא לה "דליפה". למרבה הצער, היישום הספציפי של מנגנון החיפוש memory.stat בגרסת הליבה הזו (4.9), בשילוב עם כמות הזיכרון העצומה בשרתים שלנו, פירוש הדבר שלוקח הרבה יותר זמן לשחזר את הנתונים העדכניים ביותר במטמון ולנקות זומבים מסוג cgroup.

מסתבר שבחלק מהצמתים שלנו היו כל כך הרבה זומבים של cgroup שהקריאה והשהייה עלו על שניה.

הדרך לעקיפת הבעיה של ה-cadvisor היא שחרור מיידי של מטמוני שיניים/איודות בכל המערכת, מה שמבטל מיידית את זמן הקריאה וכן את זמן השהיית הרשת במארח, מכיוון שניקוי המטמון מפעיל את דפי cgroup הזומבים המאוחסנים במטמון ומשחרר גם אותם. זה לא פתרון, אבל הוא מאשר את הסיבה לבעיה.

התברר שבגרסאות ליבה חדשות יותר (4.19+) ביצועי השיחות שופרו memory.stat, אז המעבר לקרנל הזה פתר את הבעיה. במקביל, היו לנו כלים לזהות צמתים בעייתיים באשכולות Kubernetes, לרוקן אותם בחן ולאתחל אותם. סירקנו את כל האשכולות, מצאנו צמתים עם חביון גבוה מספיק והפעלנו אותם מחדש. זה נתן לנו זמן לעדכן את מערכת ההפעלה בשרתים הנותרים.

הסתכמות

מכיוון שהבאג הזה עצר את עיבוד תור RX NIC במשך מאות אלפיות שניות, הוא גרם בו זמנית הן לאחביון גבוה בחיבורים קצרים והן לאחביון באמצע החיבור, כמו בין בקשות MySQL ומנות תגובה.

הבנה ושמירה על הביצועים של המערכות הבסיסיות ביותר, כגון Kubernetes, היא קריטית לאמינות ולמהירות של כל השירותים המבוססים עליהן. כל מערכת שאתה מפעיל נהנית משיפורי הביצועים של Kubernetes.

מקור: www.habr.com