מ-High Ceph Latency ל-Kernel Patch באמצעות eBPF/BCC

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

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

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

Ceph הוא איטי

מארח חדש נוסף לאשכול Ceph. לאחר העברת חלק מהנתונים אליו, שמנו לב שמהירות עיבוד בקשות הכתיבה על ידו נמוכה בהרבה מאשר בשרתים אחרים.

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

חוקרת את המארח

נתחיל בהסתכלות על מה שקורה בתוך תהליך ה-ceph-osd. לשם כך נשתמש perf и פלמסקופ (עוד עליו תוכל לקרוא כאן):

התמונה אומרת לנו שהפונקציה fdatasync() השקיע זמן רב בשליחת בקשה לפונקציות generic_make_request(). זה אומר שככל הנראה הסיבה לבעיות היא איפשהו מחוץ לדמון ה-OSD עצמו. זה יכול להיות הקרנל או הדיסקים. פלט ה-iostat הראה חביון גבוה בעיבוד בקשות על ידי דיסקי bcache.

כשבדקנו את המארח, גילינו שהדמון systemd-udevd צורך כמות גדולה של זמן CPU - כ-20% במספר ליבות. זו התנהגות מוזרה, אז אתה צריך לברר למה. מאז Systemd-udevd עובד עם uevents, החלטנו להסתכל עליהם צג udevadm. מסתבר שנוצרו מספר רב של אירועי שינוי עבור כל התקן בלוק במערכת. זה די חריג, אז נצטרך להסתכל מה מחולל את כל האירועים האלה.

שימוש בערכת הכלים של BCC

כפי שכבר גילינו, הקרנל (והדמון ה-ceph בקריאת המערכת) מבלה זמן רב ב generic_make_request(). בואו ננסה למדוד את המהירות של פונקציה זו. IN BCC יש כבר כלי עזר נפלא - פונקציונליות. נעקוב אחר הדמון לפי ה-PID שלו עם מרווח של שנייה אחת בין הפלטים ונוציא את התוצאה באלפיות שניות.

תכונה זו פועלת בדרך כלל במהירות. כל מה שהוא עושה הוא להעביר את הבקשה לתור מנהל ההתקן.

Bcache הוא מכשיר מורכב המורכב למעשה משלושה דיסקים:

• התקן גיבוי (דיסק שמור), במקרה זה מדובר ב-HDD איטי;
• התקן מטמון (דיסק מטמון), כאן זוהי מחיצה אחת של התקן NVMe;
• המכשיר הוירטואלי bcache שאיתו האפליקציה פועלת.

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

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

למשל ככה:

/usr/share/bcc/tools/execsnoop  | tee ./execdump

לא נציג כאן את הפלט המלא של execsnoop, אבל שורה אחת שמעניינת אותנו נראתה כך:

sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'

העמודה השלישית היא ה-PPID (PID האב) של התהליך. התהליך עם PID 5802 התברר כאחד מהחוטים של מערכת הניטור שלנו. בעת בדיקת התצורה של מערכת הניטור, נמצאו פרמטרים שגויים. הטמפרטורה של מתאם HBA נלקחה כל 30 שניות, וזה הרבה יותר מהנדרש. לאחר שינוי מרווח הבדיקה לטווח ארוך יותר, גילינו שזמן עיבוד הבקשות במארח זה כבר לא בלט בהשוואה למארחים אחרים.

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

כתיבת כלים מבוססי BCC

בואו ננסה לכתוב כלי עזר פשוט למעקב והצגה של השיחות האיטיות ביותר generic_make_request(). אנו מתעניינים גם בשם הכונן שעבורו נקראה פונקציה זו.

התוכנית פשוטה:

• הירשם kprobe על generic_make_request():
  • אנו שומרים את שם הדיסק בזיכרון, נגיש דרך ארגומנט הפונקציה;
  • אנחנו שומרים את חותמת הזמן.

• הירשם kretprobe להחזרה מ generic_make_request():
  • אנו מקבלים את חותמת הזמן הנוכחית;
  • אנו מחפשים את חותמת הזמן השמורה ומשווים אותה לזו הנוכחית;
  • אם התוצאה גדולה מהתוצאה שצוינה, אנו מוצאים את שם הדיסק השמור ומציגים אותו במסוף.

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

טקסט eBPF בתוך סקריפט python נראה כך:

bpf_text = “”” # Here will be the bpf program code “””

כדי להחליף נתונים בין פונקציות, תוכניות eBPF משתמשות טבלאות חשיש. אנחנו נעשה את אותו הדבר. נשתמש בתהליך PID כמפתח, ונגדיר את המבנה כערך:

struct data_t {
	u64 pid;
	u64 ts;
	char comm[TASK_COMM_LEN];
	u64 lat;
	char disk[DISK_NAME_LEN];
};

BPF_HASH(p, u64, struct data_t);
BPF_PERF_OUTPUT(events);

כאן אנו רושמים טבלת גיבוב בשם p, עם סוג מפתח u64 וערך של סוג struct data_t. הטבלה תהיה זמינה בהקשר של תוכנית ה-BPF שלנו. המאקרו BPF_PERF_OUTPUT רושם טבלה נוספת שנקראת אירועים, אשר משמש עבור העברת נתונים לתוך מרחב המשתמש.

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

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

void start(struct pt_regs *ctx, struct bio *bio) {
	u64 pid = bpf_get_current_pid_tgid();
	struct data_t data = {};
	u64 ts = bpf_ktime_get_ns();
	data.pid = pid;
	data.ts = ts;
	bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name);
	p.update(&pid, &data);
}

כאן הארגומנט הראשון של הפונקציה הנקראת יוחלף כארגומנט השני generic_make_request(). לאחר מכן, אנו מקבלים את ה-PID של התהליך במסגרתו אנו עובדים, ואת חותמת הזמן הנוכחית בננו-שניות. אנחנו רושמים את הכל בקובץ שנבחר טרי struct data_t data. אנו מקבלים את שם הדיסק מהמבנה ביו, אשר מועבר בעת התקשרות generic_make_request(), ושמור אותו באותו מבנה נתונים. השלב האחרון הוא הוספת ערך לטבלת הגיבוב שהוזכרה קודם לכן.

הפונקציה הבאה תיקרא בחזרה מ generic_make_request():

void stop(struct pt_regs *ctx) {
    u64 pid = bpf_get_current_pid_tgid();
    u64 ts = bpf_ktime_get_ns();
    struct data_t* data = p.lookup(&pid);
    if (data != 0 && data->ts > 0) {
        bpf_get_current_comm(&data->comm, sizeof(data->comm));
        data->lat = (ts - data->ts)/1000;
        if (data->lat > MIN_US) {
            FACTOR
            data->pid >>= 32;
            events.perf_submit(ctx, data, sizeof(struct data_t));
        }
        p.delete(&pid);
    }
}

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

ההעברה הבינארית שבה אנו משתמשים כאן נחוצה כדי לקבל את ה-GID של השרשור. הָהֵן. PID של התהליך הראשי שהתחיל את השרשור בהקשר אליו אנו עובדים. הפונקציה שאנו קוראים לה bpf_get_current_pid_tgid() מחזירה גם את ה-GID של השרשור וגם את ה-PID שלו בערך בודד של 64 סיביות.

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

בסקריפט python שיטען את הקוד הזה, עלינו להחליף את MIN_US ואת FACTOR בספי ההשהיה ויחידות הזמן, אותם נעביר דרך הארגומנטים:

bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
	bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
	label = "msec"
else:
	bpf_text = bpf_text.replace('FACTOR','')
	label = "usec"

כעת עלינו להכין את תוכנית BPF באמצעות מאקרו BPF ורשום דוגמאות:

b = BPF(text=bpf_text)
b.attach_kprobe(event="generic_make_request",fn_name="start")
b.attach_kretprobe(event="generic_make_request",fn_name="stop")

נצטרך גם לקבוע struct data_t בתסריט שלנו, אחרת לא נוכל לקרוא כלום:

TASK_COMM_LEN = 16	# linux/sched.h
DISK_NAME_LEN = 32	# linux/genhd.h
class Data(ct.Structure):
	_fields_ = [("pid", ct.c_ulonglong),
            	("ts", ct.c_ulonglong),
            	("comm", ct.c_char * TASK_COMM_LEN),
            	("lat", ct.c_ulonglong),
            	("disk",ct.c_char * DISK_NAME_LEN)]

השלב האחרון הוא פלט נתונים למסוף:

def print_event(cpu, data, size):
    global start
    event = ct.cast(data, ct.POINTER(Data)).contents
    if start == 0:
        start = event.ts
    time_s = (float(event.ts - start)) / 1000000000
    print("%-18.9f %-16s %-6d   %-1s %s   %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk))

b["events"].open_perf_buffer(print_event)
# format output
start = 0
while 1:
    try:
        b.perf_buffer_poll()
    except KeyboardInterrupt:
        exit()

התסריט עצמו זמין ב GItHub. בואו ננסה להריץ את זה על פלטפורמת בדיקה שבה fio פועל, כותב ל-bcache, ונקרא udevadm monitor:

סוף כל סוף! כעת אנו רואים שמה שנראה כמו מכשיר bcache נתקע הוא למעשה שיחת נתקע generic_make_request() עבור דיסק שמור.

חפרו לתוך הגרעין

מה בדיוק מאט במהלך שידור הבקשה? אנו רואים שהעיכוב מתרחש עוד לפני תחילת חשבונאות הבקשה, כלומר. עדיין לא החל ניהול חשבונאות של בקשה ספציפית לפלט נוסף של סטטיסטיקות עליה (/proc/diskstats או iostat). ניתן לאמת זאת בקלות על ידי הפעלת iostat תוך כדי שחזור הבעיה, או ביולנטיות של סקריפט BCC, המבוסס על ההתחלה והסיום של חשבונאות בקשה. אף אחד מכלי השירות הללו לא יציג בעיות עבור בקשות לדיסק המאוחסן.

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

ret = wait_event_interruptible(q->mq_freeze_wq,
	(atomic_read(&q->mq_freeze_depth) == 0 &&
	(preempt || !blk_queue_preempt_only(q))) ||
	blk_queue_dying(q));

בה, הקרנל ממתין לפתיחת התור. בואו נמדוד את ההשהיה blk_queue_enter():

~# /usr/share/bcc/tools/funclatency  blk_queue_enter -i 1 -m               	 
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.

 	msecs           	: count 	distribution
     	0 -> 1      	: 341  	|****************************************|

 	msecs           	: count 	distribution
     	0 -> 1      	: 316  	|****************************************|

 	msecs           	: count 	distribution
     	0 -> 1      	: 255  	|****************************************|
     	2 -> 3      	: 0    	|                                    	|
     	4 -> 7      	: 0    	|                                    	|
     	8 -> 15     	: 1    	|                                    	|

נראה שאנחנו קרובים לפתרון. הפונקציות המשמשות להקפאה/ביטול הקפאת תור הן blk_mq_freeze_queue и blk_mq_unfreeze_queue. הם משמשים כאשר יש צורך לשנות את הגדרות תור הבקשות, שעלולות להיות מסוכנות לבקשות בתור זה. כשמתקשרים blk_mq_freeze_queue() функцией blk_freeze_queue_start() המונה מוגדל q->mq_freeze_depth. לאחר מכן, הקרנל ממתין עד שהתור יתרוקן blk_mq_freeze_queue_wait().

הזמן שלוקח לנקות תור זה שווה ערך להשהייה בדיסק מכיוון שהקרנל ממתין לסיום כל הפעולות בתור. ברגע שהתור ריק, השינויים בהגדרות יחולו. אחריו זה נקרא blk_mq_unfreeze_queue(), מוריד את המונה freeze_depth.

עכשיו אנחנו יודעים מספיק כדי לתקן את המצב. הפקודה udevadm trigger גורמת להחלת ההגדרות של התקן החסימה. הגדרות אלו מתוארות בכללי udev. אנו יכולים למצוא אילו הגדרות מקפיאות את התור על ידי ניסיון לשנות אותן באמצעות sysfs או על ידי הסתכלות בקוד המקור של הליבה. אנחנו יכולים גם לנסות את כלי השירות BCC להתחקות, אשר יוציא מעקבי מחסנית של ליבה ומרחב משתמש עבור כל קריאה למסוף blk_freeze_queue, לדוגמה:

~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID 	TID 	COMM        	FUNC        	 
3809642 3809642 systemd-udevd   blk_freeze_queue
    	blk_freeze_queue+0x1 [kernel]
    	elevator_switch+0x29 [kernel]
    	elv_iosched_store+0x197 [kernel]
    	queue_attr_store+0x5c [kernel]
    	sysfs_kf_write+0x3c [kernel]
    	kernfs_fop_write+0x125 [kernel]
    	__vfs_write+0x1b [kernel]
    	vfs_write+0xb8 [kernel]
    	sys_write+0x55 [kernel]
    	do_syscall_64+0x73 [kernel]
    	entry_SYSCALL_64_after_hwframe+0x3d [kernel]
    	__write_nocancel+0x7 [libc-2.23.so]
    	[unknown]

3809631 3809631 systemd-udevd   blk_freeze_queue
    	blk_freeze_queue+0x1 [kernel]
    	queue_requests_store+0xb6 [kernel]
    	queue_attr_store+0x5c [kernel]
    	sysfs_kf_write+0x3c [kernel]
    	kernfs_fop_write+0x125 [kernel]
    	__vfs_write+0x1b [kernel]
    	vfs_write+0xb8 [kernel]
    	sys_write+0x55 [kernel]
    	do_syscall_64+0x73 [kernel]
    	entry_SYSCALL_64_after_hwframe+0x3d [kernel]
    	__write_nocancel+0x7 [libc-2.23.so]
    	[unknown]

חוקי Udev משתנים לעיתים רחוקות ובדרך כלל זה קורה בצורה מבוקרת. אז אנחנו רואים שאפילו יישום הערכים שכבר מוגדרים גורם לעלייה בעיכוב בהעברת הבקשה מהאפליקציה לדיסק. כמובן, יצירת אירועי udev כאשר אין שינויים בתצורת הדיסק (לדוגמה, ההתקן אינו מותקן/מנותק) אינו נוהג טוב. עם זאת, אנו יכולים לעזור לקרנל לא לעשות עבודה מיותרת ולהקפיא את תור הבקשות אם אין צורך בכך. שלוש קטן לְבַצֵעַ לתקן את המצב.

סיכום

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

ישנם כלי ניפוי באגים ופרופילים מעניינים נוספים המבוססים על eBPF. אחד מהם - bpftrace, המאפשר לך לכתוב One-Liner עוצמתי ותוכניות קטנות בשפה הדומה ל-awk. עוד - ebpf_exporter, מאפשר לך לאסוף מדדים ברמה נמוכה וברזולוציה גבוהה ישירות לשרת הפרומתאוס שלך, עם יכולת לקבל מאוחר יותר הדמיות יפות ואפילו התראות.

מקור: www.habr.com