Linux ma dużą liczbę narzędzi do debugowania jądra i aplikacji. Większość z nich ma negatywny wpływ na wydajność aplikacji i nie może być wykorzystana w środowisku produkcyjnym.
Kilka lat temu było - eBPF. Umożliwia śledzenie jądra i aplikacji użytkownika przy niewielkim obciążeniu i bez konieczności przebudowy programów i ładowania modułów innych firm do jądra.
Istnieje już wiele narzędzi aplikacyjnych korzystających z eBPF, a w tym artykule przyjrzymy się, jak napisać własne narzędzie do profilowania w oparciu o bibliotekę . Artykuł oparty jest na prawdziwych wydarzeniach. Przejdziemy od problemu do rozwiązania, aby pokazać, jak można wykorzystać istniejące narzędzia w określonych sytuacjach.
Ceph jest powolny
Do klastra Ceph dodano nowy host. Po migracji na niego części danych zauważyliśmy, że prędkość przetwarzania przez niego żądań zapisu była znacznie niższa niż na innych serwerach.
W przeciwieństwie do innych platform, ten host korzystał z bcache i nowego jądra Linuksa 4.15. Po raz pierwszy użyto tutaj hosta o tej konfiguracji. I w tym momencie było jasne, że teoretycznie przyczyną problemu może być wszystko.
Badanie gospodarza
Zacznijmy od przyjrzenia się temu, co dzieje się w procesie ceph-osd. Do tego użyjemy и (więcej o czym możesz przeczytać ):
Rysunek mówi nam, że funkcja fdatasync() spędził dużo czasu wysyłając żądanie do funkcji rodzajowy_make_request(). Oznacza to, że najprawdopodobniej przyczyna problemów leży gdzieś poza samym demonem OSD. Może to być jądro lub dyski. Dane wyjściowe iostatu wykazały duże opóźnienia w przetwarzaniu żądań przez dyski bcache.
Sprawdzając hosta, odkryliśmy, że demon systemd-udevd zużywa dużą ilość czasu procesora - około 20% na kilku rdzeniach. To dziwne zachowanie, więc musisz dowiedzieć się dlaczego. Ponieważ Systemd-udevd współpracuje z ueventami, postanowiliśmy je dokładnie przejrzeć monitor udevadm. Okazuje się, że dla każdego urządzenia blokowego w systemie wygenerowano dużą liczbę zdarzeń zmiany. Jest to dość niezwykłe, więc będziemy musieli przyjrzeć się temu, co generuje te wszystkie zdarzenia.
Korzystanie z zestawu narzędzi BCC
Jak już się dowiedzieliśmy, jądro (oraz demon ceph w wywołaniu systemowym) spędza dużo czasu rodzajowy_make_request(). Spróbujmy zmierzyć prędkość tej funkcji. W Istnieje już wspaniałe narzędzie - funkcjonalność. Prześledzimy demona według jego PID z 1-sekundową przerwą między wyjściami i wyślemy wynik w milisekundach.
Ta funkcja zwykle działa szybko. Jedyne, co robi, to przekazuje żądanie do kolejki sterowników urządzeń.
Pamięć podręczna to złożone urządzenie, które w rzeczywistości składa się z trzech dysków:
- urządzenie bazowe (dysk buforowany), w tym przypadku jest to powolny dysk twardy;
- urządzenie buforujące (dysk buforujący), tutaj jest to jedna partycja urządzenia NVMe;
- urządzenie wirtualne bcache, z którym działa aplikacja.
Wiemy, że transmisja żądań jest powolna, ale dla którego z tych urządzeń? Zajmiemy się tym nieco później.
Teraz wiemy, że zdarzenia mogą powodować problemy. Znalezienie, co dokładnie powoduje ich powstawanie, nie jest takie proste. Załóżmy, że jest to jakiś rodzaj oprogramowania uruchamianego okresowo. Zobaczmy, jakie oprogramowanie działa w systemie za pomocą skryptu execsnoop z tego samego . Uruchommy go i wyślijmy dane wyjściowe do pliku.
Na przykład tak:
/usr/share/bcc/tools/execsnoop | tee ./execdump
Nie pokażemy tutaj pełnego wyniku execsnoop, ale jeden interesujący nas wiersz wyglądał następująco:
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
Trzecia kolumna to PPID (nadrzędny PID) procesu. Proces z PID 5802 okazał się jednym z wątków naszego systemu monitorowania. Podczas sprawdzania konfiguracji systemu monitorowania stwierdzono błędne parametry. Temperaturę adaptera HBA mierzono co 30 sekund, czyli znacznie częściej niż to konieczne. Po zmianie interwału sprawdzania na dłuższy odkryliśmy, że opóźnienie przetwarzania żądań na tym hoście nie wyróżnia się już na tle innych hostów.
Jednak nadal nie jest jasne, dlaczego urządzenie bcache było tak wolne. Przygotowaliśmy platformę testową o identycznej konfiguracji i próbowaliśmy odtworzyć problem, uruchamiając fio na bcache, okresowo uruchamiając wyzwalacz udevadm w celu wygenerowania zdarzeń uevent.
Pisanie narzędzi opartych na BCC
Spróbujmy napisać proste narzędzie do śledzenia i wyświetlania najwolniejszych połączeń rodzajowy_make_request(). Interesuje nas także nazwa napędu, dla którego wywołano tę funkcję.
Plan jest prosty:
- Rejestr sonda na rodzajowy_make_request():
- Zapisujemy nazwę dysku w pamięci dostępnej poprzez argument funkcji;
- Zapisujemy znacznik czasu.
- Rejestr kretsonda do powrotu z rodzajowy_make_request():
- Otrzymujemy aktualny znacznik czasu;
- Szukamy zapisanego znacznika czasu i porównujemy go z bieżącym;
- Jeżeli wynik jest większy od podanego, to znajdujemy zapisaną nazwę dysku i wyświetlamy ją na terminalu.
Sondy K и kretsondy użyj mechanizmu punktu przerwania, aby zmienić kod funkcji w locie. Możesz czytać и artykuł na ten temat. Jeśli spojrzysz na kod różnych narzędzi w , wtedy widać, że mają identyczną strukturę. Zatem w tym artykule pominiemy analizowanie argumentów skryptu i przejdziemy do samego programu BPF.
Tekst eBPF wewnątrz skryptu Pythona wygląda następująco:
bpf_text = “”” # Here will be the bpf program code “””
Do wymiany danych pomiędzy funkcjami służą programy eBPF . Zrobimy to samo. Jako klucz wykorzystamy PID procesu, a strukturę zdefiniujemy jako wartość:
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);
Tutaj rejestrujemy tablicę mieszającą o nazwie p, z typem klucza u64 i wartość typu struktura danych_t. Tabela będzie dostępna w kontekście naszego programu BPF. Makro BPF_PERF_OUTPUT rejestruje kolejną tabelę o nazwie wydarzenia, do którego się używa w przestrzeń użytkownika.
Mierząc opóźnienia pomiędzy wywołaniem funkcji a powrotem z niej, czy pomiędzy wywołaniami różnych funkcji, należy wziąć pod uwagę, że odbierane dane muszą należeć do tego samego kontekstu. Innymi słowy trzeba pamiętać o możliwości równoległego uruchamiania funkcji. Mamy możliwość zmierzenia opóźnienia między wywołaniem funkcji w kontekście jednego procesu a powrotem z tej funkcji w kontekście innego procesu, ale prawdopodobnie jest to bezużyteczne. Dobrym przykładem byłby tutaj , gdzie klucz tablicy mieszającej jest ustawiony na wskaźnik do żądanie struktury, co odzwierciedla jedno żądanie dysku.
Następnie musimy napisać kod, który uruchomi się po wywołaniu badanej funkcji:
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);
}
Tutaj pierwszy argument wywoływanej funkcji zostanie zastąpiony drugim argumentem . Następnie otrzymujemy PID procesu, w kontekście którego pracujemy, oraz aktualny znacznik czasu w nanosekundach. Wszystko zapisujemy w świeżo wybranym struktura danych_t danych. Nazwę dysku otrzymujemy ze struktury bio, który jest przekazywany podczas wywoływania rodzajowy_make_request()i zapisz go w tej samej strukturze dane. Ostatnim krokiem jest dodanie wpisu do tablicy mieszającej, o którym wspomniałem wcześniej.
Po powrocie z: zostanie wywołana następująca funkcja rodzajowy_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);
}
}
Ta funkcja jest podobna do poprzedniej: dowiadujemy się o PID procesu i znaczniku czasu, ale nie przydzielamy pamięci dla nowej struktury danych. Zamiast tego przeszukujemy tablicę mieszającą pod kątem już istniejącej struktury za pomocą klucza == bieżący PID. Jeśli struktura zostanie znaleziona, wówczas znajdujemy nazwę działającego procesu i dodajemy ją do niej.
Przesunięcie binarne, którego tutaj używamy, jest potrzebne do uzyskania GID wątku. te. PID głównego procesu, który uruchomił wątek, w kontekście którego pracujemy. Funkcja, którą wywołujemy zwraca zarówno GID wątku, jak i jego PID w jednej wartości 64-bitowej.
Podczas wysyłania do terminala nie jesteśmy obecnie zainteresowani strumieniem, ale interesuje nas główny proces. Po porównaniu powstałego opóźnienia z zadanym progiem przekazujemy naszą strukturę dane do przestrzeni użytkownika za pośrednictwem tabeli wydarzenia, po czym usuwamy wpis z p.
W skrypcie Pythona, który załaduje ten kod, musimy zastąpić MIN_US i FACTOR progami opóźnienia i jednostkami czasu, które przekażemy przez argumenty:
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"
Teraz musimy przygotować program BPF poprzez i zarejestruj próbki:
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")
Będziemy musieli również ustalić struktura danych_t w naszym skrypcie, inaczej nie będziemy mogli nic odczytać:
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)]
Ostatnim krokiem jest wysłanie danych do terminala:
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()
Sam skrypt jest dostępny pod adresem . Spróbujmy uruchomić go na platformie testowej, na której działa fio, zapiszmy do bcache i wywołajmy monitor udevadm:
Wreszcie! Teraz widzimy, że to, co wyglądało na zawieszające się urządzenie bcache, w rzeczywistości jest wywołaniem opóźniającym rodzajowy_make_request() dla dysku buforowanego.
Zajrzyj do jądra
Co dokładnie spowalnia podczas transmisji żądania? Widzimy, że opóźnienie występuje jeszcze przed rozpoczęciem rozliczania żądań, tj. rozliczanie konkretnego żądania dalszego wyprowadzania statystyk na ten temat (/proc/diskstats lub iostat) jeszcze się nie rozpoczęło. Można to łatwo zweryfikować, uruchamiając iostat podczas odtwarzania problemu lub , który opiera się na rozpoczęciu i zakończeniu rozliczania żądań. Żadne z tych narzędzi nie będzie wyświetlać problemów z żądaniami kierowanymi do dysku buforowanego.
Jeśli spojrzymy na funkcję rodzajowy_make_request(), wtedy zobaczymy, że zanim żądanie rozpocznie rozliczanie, wywoływane są jeszcze dwie funkcje. Pierwszy - rodzajowy_make_request_checks(), sprawdza zasadność żądania dotyczącego ustawień dysku. Drugi - , co stanowi ciekawe wyzwanie :
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));
W nim jądro czeka na odblokowanie kolejki. Zmierzmy opóźnienie 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 | |
Wygląda na to, że jesteśmy blisko rozwiązania. Funkcje używane do blokowania/odmrażania kolejki to и . Stosuje się je, gdy konieczna jest zmiana ustawień kolejki żądań, co jest potencjalnie niebezpieczne dla żądań znajdujących się w tej kolejce. Kiedy dzwonisz blk_mq_freeze_queue() funkcjonować licznik jest zwiększany q->mq_freeze_głębia. Następnie jądro czeka, aż kolejka się opróżni .
Czas potrzebny na wyczyszczenie tej kolejki jest równy opóźnieniu dysku, ponieważ jądro czeka na zakończenie wszystkich operacji w kolejce. Gdy kolejka będzie pusta, zmiany ustawień zostaną zastosowane. Po czym się to nazywa , zmniejszając licznik zamrożenie_głębokość.
Teraz wiemy wystarczająco dużo, aby naprawić sytuację. Polecenie wyzwalacza udevadm powoduje zastosowanie ustawień urządzenia blokowego. Ustawienia te są opisane w zasadach udev. Możemy dowiedzieć się, które ustawienia blokują kolejkę, próbując je zmienić za pomocą sysfs lub patrząc na kod źródłowy jądra. Możemy także wypróbować narzędzie BCC , który wyświetli ślady stosu jądra i przestrzeni użytkownika dla każdego wywołania terminala blk_freeze_queuena przykład:
~# /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]
Zasady Udev zmieniają się dość rzadko i zwykle dzieje się to w sposób kontrolowany. Widzimy więc, że nawet zastosowanie już ustawionych wartości powoduje skok opóźnienia w przesyłaniu żądania z aplikacji na dysk. Oczywiście generowanie zdarzeń udev, gdy nie ma żadnych zmian w konfiguracji dysku (np. urządzenie nie jest podłączone/odłączone) nie jest dobrą praktyką. Możemy jednak pomóc jądru nie wykonywać niepotrzebnej pracy i zamrażać kolejkę żądań, jeśli nie jest to konieczne. poprawić sytuację.
Wnioski
eBPF jest bardzo elastycznym i potężnym narzędziem. W artykule przyjrzeliśmy się jednemu praktycznemu przypadkowi i zademonstrowaliśmy niewielką część tego, co można zrobić. Jeśli jesteś zainteresowany rozwojem narzędzi BCC, warto się temu przyjrzeć , który dobrze opisuje podstawy.
Istnieją inne interesujące narzędzia do debugowania i profilowania oparte na eBPF. Jeden z nich - , który umożliwia pisanie potężnych, jednowierszowych programów i małych programów w języku podobnym do awk. Inny - , umożliwia gromadzenie wskaźników niskiego poziomu i wysokiej rozdzielczości bezpośrednio na serwerze Prometheus, z możliwością późniejszego uzyskiwania pięknych wizualizacji, a nawet alertów.
Źródło: www.habr.com