Το Linux διαθέτει μεγάλο αριθμό εργαλείων για τον εντοπισμό σφαλμάτων στον πυρήνα και τις εφαρμογές. Τα περισσότερα από αυτά έχουν αρνητικό αντίκτυπο στην απόδοση της εφαρμογής και δεν μπορούν να χρησιμοποιηθούν στην παραγωγή.
Πριν από μερικά χρόνια υπήρχε
Υπάρχουν ήδη πολλά βοηθητικά προγράμματα εφαρμογών που χρησιμοποιούν eBPF και σε αυτό το άρθρο θα δούμε πώς να γράψετε το δικό σας βοηθητικό πρόγραμμα δημιουργίας προφίλ με βάση τη βιβλιοθήκη
Ο Κεφ είναι αργός
Ένας νέος κεντρικός υπολογιστής προστέθηκε στο σύμπλεγμα Ceph. Μετά τη μετεγκατάσταση ορισμένων δεδομένων σε αυτό, παρατηρήσαμε ότι η ταχύτητα επεξεργασίας των αιτημάτων εγγραφής από αυτό ήταν πολύ χαμηλότερη από ό,τι σε άλλους διακομιστές.
Σε αντίθεση με άλλες πλατφόρμες, αυτός ο κεντρικός υπολογιστής χρησιμοποιούσε bcache και τον νέο πυρήνα Linux 4.15. Αυτή ήταν η πρώτη φορά που χρησιμοποιήθηκε εδώ μια σειρά από αυτήν τη διαμόρφωση. Και εκείνη τη στιγμή ήταν ξεκάθαρο ότι η ρίζα του προβλήματος θα μπορούσε θεωρητικά να είναι οτιδήποτε.
Ερευνώντας τον οικοδεσπότη
Ας ξεκινήσουμε εξετάζοντας τι συμβαίνει μέσα στη διαδικασία ceph-osd. Για αυτό θα χρησιμοποιήσουμε
Η εικόνα μας λέει ότι η συνάρτηση fdatasync() ξόδεψε πολύ χρόνο στέλνοντας ένα αίτημα στις λειτουργίες generic_make_request(). Αυτό σημαίνει ότι πιθανότατα η αιτία των προβλημάτων βρίσκεται κάπου έξω από τον ίδιο τον δαίμονα του osd. Αυτό μπορεί να είναι είτε ο πυρήνας είτε οι δίσκοι. Η έξοδος iostat έδειξε υψηλή καθυστέρηση στην επεξεργασία αιτημάτων από δίσκους bcache.
Κατά τον έλεγχο του κεντρικού υπολογιστή, διαπιστώσαμε ότι ο δαίμονας systemd-udevd καταναλώνει μεγάλο χρονικό διάστημα CPU - περίπου 20% σε πολλούς πυρήνες. Αυτή είναι περίεργη συμπεριφορά, οπότε πρέπει να μάθετε γιατί. Δεδομένου ότι το Systemd-udevd δουλεύει με uevents, αποφασίσαμε να τα δούμε αναλυτικά οθόνη udevadm. Αποδεικνύεται ότι ένας μεγάλος αριθμός γεγονότων αλλαγής δημιουργήθηκε για κάθε μπλοκ συσκευή στο σύστημα. Αυτό είναι αρκετά ασυνήθιστο, επομένως θα πρέπει να δούμε τι δημιουργεί όλα αυτά τα γεγονότα.
Χρήση της εργαλειοθήκης BCC
Όπως έχουμε ήδη ανακαλύψει, ο πυρήνας (και ο δαίμονας ceph στην κλήση συστήματος) ξοδεύει πολύ χρόνο στο generic_make_request(). Ας προσπαθήσουμε να μετρήσουμε την ταχύτητα αυτής της συνάρτησης. ΣΕ
Αυτή η δυνατότητα συνήθως λειτουργεί γρήγορα. Το μόνο που κάνει είναι να περάσει το αίτημα στην ουρά του προγράμματος οδήγησης της συσκευής.
Bcache είναι μια πολύπλοκη συσκευή που στην πραγματικότητα αποτελείται από τρεις δίσκους:
- συσκευή υποστήριξης (αποθηκευμένος δίσκος), σε αυτήν την περίπτωση είναι ένας αργός σκληρός δίσκος.
- συσκευή προσωρινής αποθήκευσης (caching disk), εδώ αυτό είναι ένα διαμέρισμα της συσκευής NVMe.
- την εικονική συσκευή bcache με την οποία εκτελείται η εφαρμογή.
Γνωρίζουμε ότι η μετάδοση αιτημάτων είναι αργή, αλλά για ποια από αυτές τις συσκευές; Θα ασχοληθούμε με αυτό λίγο αργότερα.
Γνωρίζουμε τώρα ότι οι εκδηλώσεις είναι πιθανό να προκαλέσουν προβλήματα. Το να βρεις τι ακριβώς προκαλεί τη γενιά τους δεν είναι τόσο εύκολο. Ας υποθέσουμε ότι πρόκειται για κάποιο είδος λογισμικού που εκκινείται περιοδικά. Ας δούμε τι είδους λογισμικό εκτελείται στο σύστημα χρησιμοποιώντας ένα σενάριο execsnoop από το ίδιο
Για παράδειγμα όπως αυτό:
/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 χρησιμοποιήστε έναν μηχανισμό σημείου διακοπής για να αλλάξετε τον κώδικα συνάρτησης εν κινήσει. Μπορείς να διαβάσεις
Το κείμενο eBPF μέσα στο σενάριο της python μοιάζει με αυτό:
bpf_text = “”” # Here will be the bpf program code “””
Για την ανταλλαγή δεδομένων μεταξύ συναρτήσεων, τα προγράμματα eBPF χρησιμοποιούν
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():
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 της διαδικασίας και τη χρονική σήμανση, αλλά δεν εκχωρούμε μνήμη για τη νέα δομή δεδομένων. Αντίθετα, αναζητούμε στον πίνακα κατακερματισμού μια ήδη υπάρχουσα δομή χρησιμοποιώντας το κλειδί == τρέχον PID. Εάν βρεθεί η δομή, τότε μαθαίνουμε το όνομα της διαδικασίας που εκτελείται και την προσθέτουμε σε αυτήν.
Η δυαδική μετατόπιση που χρησιμοποιούμε εδώ είναι απαραίτητη για να λάβουμε το GID νήματος. εκείνοι. PID της κύριας διαδικασίας που ξεκίνησε το νήμα στο πλαίσιο του οποίου εργαζόμαστε. Η συνάρτηση που ονομάζουμε
Κατά την έξοδο στο τερματικό, αυτή τη στιγμή δεν μας ενδιαφέρει το νήμα, αλλά μας ενδιαφέρει η κύρια διαδικασία. Αφού συγκρίνουμε την προκύπτουσα καθυστέρηση με ένα δεδομένο όριο, περνάμε τη δομή μας ημερομηνία στο χώρο χρήστη μέσω πίνακα εκδηλώσεις, μετά την οποία διαγράφουμε την καταχώρηση από 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 μέσω
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()
Το ίδιο το σενάριο είναι διαθέσιμο στο
Τελικά! Τώρα βλέπουμε ότι αυτό που έμοιαζε με μια συσκευή bcache που καθυστερεί είναι στην πραγματικότητα μια κλήση στασιμότητας generic_make_request() για έναν αποθηκευμένο δίσκο.
Σκάψτε στον πυρήνα
Τι ακριβώς επιβραδύνεται κατά τη μετάδοση αιτήματος; Βλέπουμε ότι η καθυστέρηση συμβαίνει ακόμη και πριν από την έναρξη της λογιστικής αίτησης, δηλ. Η λογιστικοποίηση ενός συγκεκριμένου αιτήματος για περαιτέρω παραγωγή στατιστικών σχετικά με αυτό (/proc/diskstats ή iostat) δεν έχει ακόμη ξεκινήσει. Αυτό μπορεί εύκολα να επαληθευτεί εκτελώντας το iostat κατά την αναπαραγωγή του προβλήματος ή
Αν δούμε τη συνάρτηση generic_make_request(), τότε θα δούμε ότι πριν ξεκινήσει η λογιστική του αιτήματος, καλούνται δύο ακόμη συναρτήσεις. Πρώτα - generic_make_request_checks(), πραγματοποιεί ελέγχους για τη νομιμότητα του αιτήματος σχετικά με τις ρυθμίσεις του δίσκου. Δεύτερο -
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 | |
Φαίνεται ότι είμαστε κοντά σε λύση. Οι λειτουργίες που χρησιμοποιούνται για το πάγωμα/αποπάγωμα μιας ουράς είναι
Ο χρόνος που χρειάζεται για την εκκαθάριση αυτής της ουράς είναι ισοδύναμος με τον λανθάνοντα χρόνο δίσκου, καθώς ο πυρήνας περιμένει να ολοκληρωθούν όλες οι λειτουργίες στην ουρά. Μόλις αδειάσει η ουρά, εφαρμόζονται οι αλλαγές ρυθμίσεων. Μετά από το οποίο ονομάζεται
Τώρα ξέρουμε αρκετά για να διορθώσουμε την κατάσταση. Η εντολή ενεργοποίησης udevadm προκαλεί την εφαρμογή των ρυθμίσεων για τη συσκευή αποκλεισμού. Αυτές οι ρυθμίσεις περιγράφονται στους κανόνες udev. Μπορούμε να βρούμε ποιες ρυθμίσεις παγώνουν την ουρά προσπαθώντας να τις αλλάξουμε μέσω sysfs ή κοιτάζοντας τον πηγαίο κώδικα του πυρήνα. Μπορούμε επίσης να δοκιμάσουμε το βοηθητικό πρόγραμμα BCC
~# /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. Ενας από αυτούς -
Πηγή: www.habr.com