pl  |  en

Sysdig – jak mogłem bez tego żyć?

Jakie zapytania do MySQLa korzystają z tabel tymczasowych? Który proces najbardziej obciąża sieć? Gdzie jest wąskie gardło aplikacji? ♫ … możesz wiedzieć jeśli chcesz … ♫ Sysdig to nowe narzędzie do śledzenia działania systemu inspirowane stracem, solarisowym dtracem i tcpdumpem, a na czubku tortu wisienka z Lua. Jedno z kategorii „jak ja mogłem wcześniej bez tego żyć”?

Pewnie często diagnozujecie problemy wydajnościowe. Coś nie działa lub trzeba sprawdzić jak to coś zachowuje się w bebechach. Bez odpowiednich narzędzi proces działający w systemie jest jak czarna skrzynka. Coś wchodzi, coś wychodzi, ale co się dzieje w środku?



sys

Jeżeli przyjrzeć się z bliska, to cała komunikacja dowolnego procesu w Linuxie ze światem odbywa się przez wywołania systemowe. Fakt, są jeszcze sygnały czy pamięć współdzielona, natomiast zdecydowana większość interakcji ze światem to właśnie wywołania systemowe.

Na tej przykładowej architekturze, w tej wersji jest ich około 300. Prawie wszystkie są odpowiednio udokumentowane.

sysdig.005

Oto co proces może zrobić w systemie. Otworzyć plik, zapisać plik, przeczytać, otworzyć socket sieciowy, poczekać na coś, co się stało, zabić proces, otworzyć nowy proces i tak dalej. Jeżeli mamy możliwość podejrzenia wywołań systemowych, jakie dany proces robi, to otrzymujemy bardzo duży wgląd w to, co się w danym procesie dzieje (np. dlaczego nie działa). Jest do tego narzędzie linuksowe wbudowane od zawsze, które wypisuje wszystkie wywołania systemowe, jakie wykonuje dany proces. Można w ten sposób bardzo dokładnie zdiagnozować co się dzieje, czemu nie działa, gdzie nie ma uprawnień. Jest to strace – super podstawowe narzędzie. Jeśli jeszcze go nie używaliście, to najwyższy czas zacząć. Chyba, że od razu przejdziecie na Sysdiga.
Strace ma jeden problem – jeżeli uruchomicie sobie dd z /dev/zero do /dev/null, czyli wywołacie jak najwięcej wywołań systemowych w jak najkrótszym czasie, bez żadnego tracera na tym sprzęcie osiąniecie wynik 3 GB/sekunda czyli ok 3 milionów wywołań systemowych na sekundę. To jest całkiem przyzwoicie, natomiast, jeśli uruchomicie dokładnie to samo dd pod stracem, który nawet pisze do /dev/null to niestety wydajność spadnie pięćdziesięciokrotnie. To jest przypadek szczególny – najgorszy możliwy do śledzenia aplikacji. dd wykonuje masę wywołań systemowych jak najszybciej i w konsekwencji testujemy tylko i wyłącznie sam interfejs do do syscalli.  Pięćdziesięciokrotny spadek wydajności – to jednak dosyć smutne i powoduje to, że strace’a efektywnie bardzo ciężko używać w środowisku produkcyjnym. Ma tak dużo rzeczy do zrobienia, że zaburza działanie systemu. Jeżeli macie problem wydajnościowy i wepniecie się stracem w dany proces to macie kolejny problem wydajnościowy, który jest pięćdziesiąt razy większy. Wtedy maszyna idzie do piachu, bo nie radzi sobie zupełnie z takim obciążeniem i trzeba szukać innych rozwiązań.

sysdig.009

To jest slajd zapożyczony z prezentacji Brendana Gregga. Gość robi od lat tą samą prezentację, ale z roku na rok jest ona coraz lepsza. Polecam sobie przejrzeć. Widać, że wchodzimy w świat zupełnie nieustandaryzowany. Są to rozwiązania stricte linuksowe. O ile strace korzysta z mechanizmów, które są w miarę powszechnie używane, o tyle te rozwiązania wykorzystują mechanizmy, które są całkowicie specyficzne dla Linuksa. Dzięki temu działają dużo szybciej i lżej. 

To w miarę wiarygodny krajobraz tego, co dzieje się na bieżąco w dynamicznym śledzeniu linuksów w 2014 roku. Niestety Dtrace i kTap byłyby kiedyś fajne, ale dziś zupełnie nie działają. Pozostałe narzędzia też bywają uciążliwe, wystarczy inny usecase i wymagają innego przygotowania. Dlatego korzystam z Sysdiga, który nie do końca pasuje do tego schematu. Perf, ftrace, EBPF służą do zupełnie czego innego. Z wszystkich tu wymienionych Sysdig jest właściwie jedyną rozsądną alternatywą dla strace’a. Tak, jak  Brendan określił, Sysdig jest łatwy w użyciu (moim zdaniem dużo łatwiejszy od pozostałych tracerów dynamicznych), ma dość ograniczony obszar zainteresowań, nie umie aż tak dużo, ale to co wystawia jest bardzo fajne i przyjemne w użyciu.

Jak Sysdig zachowuje się w praktyce? Po uruchomieniu Sysdig od razu Was zarzyga wszystkimi syscallami działającymi w systemie. Jest tego naprawdę masa. Można to wyciąć headem, żeby się nie utopić. Następnie, tak po łebkach, w domyślnym widoku, Sysdig zwraca kolejny numer zdarzenia, czas, kiedy to zdarzenie wystąpiło, numer i nazwa procesu, czyli śledzony jest cały system, wszystkie procesory, procesy, wątki. Na poniższym slajdzie widzimy, jak, w losowo wybranym momencie, udevd sobie stwierdził, że w sumie musi sobie coś przeczytać.

 sysdig.011

Kolejny element to nazwa zdarzenia, który w większości przekłada na wywołania systemowe, aczkolwiek nie zawsze. Tutaj switch to jest jedyne zdarzenie, które nie jest wywołaniem systemowym, a przełączeniem kontekstu. Zwróćmy uwagę strzałki w lewo i prawo symbolizujące kierunek zdarzenia.

sysdig.015

Pokazują, że każdy syscall ma dwa zdarzenia z Sysdiga. Kiedy dany syscall się zaczął, kiedy się skończył. Bardzo jasno widać ile dane wywołanie systemowe trwało i w ten sposób znaleźć co działa wolno, gdzie jest wąskie gardło. Każde zdarzenie ma zestaw arbitralnych atrybutów. To zależy od konkretnego zdarzenia. Na przykład switch posiada szczegóły na temat procesu, na który będzie przełączony kontekst. Read, to znaczy: dane przeczytałem itd. Jest tego dużo, ale też jest to nienajgorzej udokumentowane. Można sobie wylistować wszystkie zdarzenia, które Sysdig obsługuje. Są też podane parametry wszystkich eventów. Najlepiej to sprawdzić na żywo. Dobrze działa na produkcji.

Wracając do kwestii wydajności. Mamy przykładowe dd, które zamęcza kernel bezsensownymi syscallami. dd wywołuje jakieś wywołanie systemowe, kernel wykonuje swoje i zwraca wynik. 3 miliony zapytań na sekundę. Dopniemy do tego strace’a i przez mechanizm ptrace zadziała to tak, że dd wykona wywołanie systemowe i dostanie SIGSTOP. strace zostanie powiadomiony, że dd chciało wykonać dany syscall. strace wydłubie tę informacje z zatrzymanego dd (sprawdzi, co w zasadzie miał zrobić). Na tym etapie strace powie „no to dobra, kontynnuj” i sterowanie wróci do dd.  Syscall się wykona, potem zostanie zatrzymany i tak w kółko. Widać teraz skąd się bierze ten procesowy narzut powodowany przez strace’a. Za każdym wywołaniem systemowym trzeba się od niego odbić i zaakceptować to, że dd chce to wywołanie zrobić. Sysdig działa zupełnie inaczej, podobnie do dtrace’a z Solarisa. W momencie kiedy dd wykonuje wywołanie systemowe nic mu nie przerywa. Kernel zapisuje informacje o wykonujących się syscallach i nachodzących zdarzeniach do bufora cyklicznego. Z tego też bufora informacje czyta sobie userspace’owy Sysdig. Sysdig nie ma tu takiego zestawu możliwości jak strace, czyli nie może zabronić tego syscalla, albo zmodyfikować coś w procesie, ale dzięki temu ma większą wydajność. W przedstawionym przypadku to prawie 900MB/s, czyli dochodzimy powoli do miliona syscalli na sekundę.

sysdig.020

Solarisowy dtrace jest przez wielu uważany za totalne apogeum w kwestii trace’owania dynamicznego – jest najlepszym co ludzkość mogła wymyślić i nikt już mu nie dorówna. Tymczasem dwukrotnie spowalnia działanie syscalli. Bez niego mielibyśmy wydajność ponad 1,5GB/s. Osiągnięty wynik oznacza, że można spokojnie używać Sysdiga na produkcji, np. uruchomić dowolny stresstest, benchmarki, podpiąć się sysdigiem i nie będzie tutaj dużego narzutu. System będzie działał dalej, najwyżej z większym obciążeniem CPU. Jest to podstawowa zaleta Sysdiga. Można sobie tego z zamkniętymi oczami używać i śledzić problemy w momencie, kiedy one rzeczywiście występują, zamiast próbować je odtwarzać. Nie trzeba wróżyć z fusów, co i jak to się naprawdę stało.

 

Filtry

Kluczowym ficzerem Sysdiga są filtry. Pokażę tylko przykładowe. W tym momencie jest ich 88 i nie ma sensu opisywać wszystkich. Ich omówienie to idealny sposób, by pokazać co Sysdig potrafi. Można filtrować dostępy do dyskryptorów po nazwie, czyli pełnej ścieżce do pliku. Można po adresie IP danego socketu, PIDzie lub jego dowolnym potomku. Osobiście wierciłem o to dziurę w brzuchu twórcom Sysdiga i koniec końców dopisali taką opcję. Przydatny jest także filtr pokazujący ile czasu wykonywał się dany syscall. Dzięki niemu możecie zobaczyć np. wszystkie syscalle trwające dłużej niż sekundę.

sysdig.022

Filtry są bardzo łatwe w użyciu. Można je przekazać jako jeden string, można jako osobne argumenty. Przykładowo, tu mamy widok wszystkich dostępów do plików zawierających “shadow” w nazwie, a na drugim terminalu cat /etc/shadow, które wywaliło się z EACCES (bo był to zwykły użytkownik bez uprawnień). Tym filtrem można składać trochę bardziej skomplikowane wydarzenia. Używaliśie kiedyś podsystemu do audytu w Linuxie? Ja próbowałem i szczerze mówiąc nie udało mi się zrobić z tym nic sensownego. Natomiast tą jedną linijką Sysdiga załatwiamy większość usecase’ów, np. syscalle które się wywaliły ze względu na brak uprawnień.

sysdig.023
Kolejna fajna rzecz związana z filtrami Sysdiga to fakt, że są one częściowo zaimplementowane w jądrze. Jeżeli zaczniecie trace’ować czy też sysdigować filtrem, w który się nie łapie jakiś bieżący proces, to narzut jest dużo mniejszy. Śledzimy wszystkie procesy, które nazywają się not_dd, po czym uruchamiamy dd. Dd uruchamia ponownie milion syscalli w jak najkrótszym czasie, a my mamy uruchomionego sysdiga gdzieś w tle. Wiadomo, jest narzut – nie działa tak szybko, jak bez żadnego trace’owania, natomiast widać, że wydajność mimo wszystko podskoczyła. Jeśli macie proces w systemie, który jest strasznie ciężki,  ale jego nie trace’ujecie, to nie powinien w ogóle odczuć obciążenia. Na tej samej zasadzie działa to ze strace’em. Strace się wpina w pojedyncze procesy, natomiast tam narzut jest gigantyczny, więc i tak go odczujecie.

 

Formatowanie wyjścia

Rzecz, z którą można sporo fajnych rzeczy zrobić to formatowanie wyjścia z Sysdiga. Wygląda to podobnie do filtrów. Przekazuje się format string, w którym dostępne są podobne elementy, jak w filtrach. Sysdig wypisuje tylko te wartości, te atrybuty zdarzenia, które tam podacie. Można użyć tego do bardziej przejrzystego sformatowania wyjścia. Jeśli nie potrzebujecie w każdej linijce pełnej daty, PIDu, numeru procesora, możecie je wyciąć. Jest też masa fajnych rzeczy, których nie ma domyślnie w outpucie Sysdiga, a się przydają. Zobaczmy evt.latency, które tutaj jest rozbite osobno na część sekundową i nanosekundową.

sysdig.026

Można użyć po prostu evt.latency. To goła liczba nanosekund bez zer z przodu. Przydaje się do sortowania (to są normalne, sortowalne liczby. Tak jest trochę łatwiej). Widzimy ile trwał każdy syscall. fd.type contains ip, czyli IPv4 lub IPv6 i fd.sport nie jest równy 22 – żeby wyciąć sesję ssh, na której miałem uruchomionego tego Sysdiga. Inaczej sam się śledzi i generuje coraz więcej ruchu. Wyniki stają się nieczytelne. Widać tu jakieś połączenie do Googla, które w miarę szybko poszło. Miało “sendto” trwające kilka mikrosekund i bardzo krótkie “recvfrom”. W Sysdigu można dodawać też parametry, których domyślnie nie ma, żeby analizować je w inny sposób. Czas syscalla, czas od rozpoczęcia trace’a, od rozpoczęcia syscalla – to wszystko jest dostępne i pozwala lepiej i łatwiej analizować problemy wydajnościowe.

 

Scap

Inny killer ficzer (naprawdę killer, w porównaniu ze stracem) to rzecz prosta, jak konstrukcja cepa… Mechanizm pozwalający zapisać wszystkie syscalle wykonujące się w danym momencie. Zamiast analizować je na żywo online, możecie zrzucić je do pliku. Analogicznie jak tcpdump -w jest w stanie zrobić pcapy. Nazywa tego ficzera to scap – pod spodem ma podobny format co w pcap. Teraz wyobraźcie sobie, że coś nie działa w systemie, wywalił się serwer, jakaś usługa, coś wybuchło i trzeba to jak najszybciej przywrócić do działania. Także przeanalizować co się stało, by rozwiązać problem definitywnie, a nie po prostu ustawić z crona restart całego serwera co godzinę. Jeżeli teraz będziecie się bawić stracem, czy innymi tego typu narzędziami bez możliwości zrzutu do pliku, to nie będzie komfortowa praca. Siedzicie i rozwiązujecie problem, a klient dyszy Wam na kark „kiedy będzie działać, kiedy będzie działać, kiedy będzie działać” . Z Sysdigiem można inaczej: sysdig -w, zostawiacie to na chwilę, powtarzacie problem, żeby wybuchło i wtedy przywracacie usługę, restartujecie czy też robicie coś by przywrócić system do działania. Potem, już na spokojnie, siadacie sobie z kawką, czy tam z browarkiem. sysdig -r i dobieracie parametry po kolei, analizujecie żeby ustalić przyczynę. Nikt Was nie pogania, bo usługi wszystkie działają.
Drugi przypadek użycia tego samego ficzera to benchmarki. Dzięki niemu można uruchomić np. jeden stresstest i zapisać sobie wyniki do pliku, a potem też na spokojnie analizować, mielić te dane, konwertować, zrobić ładne wykresy. Jeśli zapomnieliście czegoś zrobić w jakimś trace’ie, to trzeba te benchmarki uruchamiać jeszcze raz. Jeśli to śrowisko, w którym nie koniecznie te benchmarki możecie robić (np. produkcyjny serwer) to uruchamiacie je w nocy, żeby nie przeszkadzać ludziom. W efekcie musicie czekać do nocy coś zrobić jeszcze raz. W sysdigu wystarczy -w, -r, zapis do pliku i znowu można to z kawką, czy browarkiem spokojnie analizować.

 

Dłutka

Kolejna w miarę unikalna rzecz dla Sysdiga to chisel (dłutko). Jak już sobie coś wykopiecie sysdigiem, to później łatwo chiselem to sobie obrobić, żeby było ładne i błyszczące. To są po prostu skrypty z Lua, które przychodzą z sysdigiem, a które też możecie pisać sami. Dzięki nim możecie np. podpiąć własne funkcję pod każde zdarzenie, które przychodzi na sysdiga. Chisel umożliwia własną analizę rzeczy bardziej skomplikowanych, niż pozwalają filtry czy formatowanie wyjścia, które macie domyślnie. Można to sobie wszystko wylistować (-cl). Sysdig -i pokaże Wam informacje o konkretnym skrypcie. -c to nazwa i ewentualne argumenty. Te dłutka mogą mieć swoje własne argumenty, które same obsługują, same parsują. Można do tego używać dodatkowo wszystkich tych parametrów, które oferuje Sysdig. Oznacza to, że możecie sobie uruchomić takie dłutko, ale tylko na procesach MySQLa, albo tylko na procesach danego użytkownika, albo tylko syscalle, które trwały krócej niż 10 milisekund. Po połączeniu filtrów z tymi dłutkami można sporo fajnych rzeczy robić. Nie będę opisywał ich wszystkich. Dłutek jest obecnie 37. Każdy to prosty skrypt w Lua. Możecie sobie dp tego zajrzeć. Chisele także są fajnie udokumentowane. Niektóre nie wystawiają żadnej funkcjonalności dla użytkownika końcowego, są tylko pomocniczymi narzędziami typu parsowanie, generowanie JSONa, obsługa terminala ANSI, wygląd a’la top, czyli odświeżanie ekranu sekwencjami ANSI.

 sysdig.031

Oto przykładowy zestaw skryptów, który służy do znajdowania wąskich gardeł – czy to jest zbyt wolny dostęp do plików, czy do sieci, czy zbyt długo trwające procesy. Są też bardzo fajne dłutka, które pokazują najczęściej używane, najgorętsze pliki albo procesy, które używają najwięcej I/O. Logujecie się na maszynę, I/O jest 100%, wszystko umiera, a więc sysdig -c topfiles_time i od razu widzicie pliki, które używają najwięcej IO, których jest najwięcej dostępów. Od razu też możecie sobie zobaczyć, który to proces i zrobić mu to, na co sobie zasłużył.
Sysdig można też traktować jako narzędzie do wspomagania audytów bezpieczeństwa. Są dłutka pokazujące PIDy sesji na których zalogowani są użytkownicy. Fajny jest skrypt spy_users. Pozwala na podsłuchiwanie użytkowników – co robią, co wpisują w shellu, jakie zewnętrzne programy uruchamiają. Można sprawdzić co ktoś inny robi, bez zaglądania mu przez ramię. Na blogu Sysdiga jest fajny posta o tym, jak jego twórcy postawili honey pot i Sysdigiem sprawdzali co im robił skript kiddie jak się złapał.

 

Zamiast netstata i Isofa 

Na sysdigowym blogasku znajdziecie inny fajny ficzer. Znacie na pewno marzędzia tylu lsof, ps, netstat. Sysdig oferuje je w formie chisels. Dzięki temu zyskujemy np. lsofa czy netstata z możliwością podróży w czasie. Wystarczy zrzucić stan systemu (sysdig -w), a potem, przy wystąpieniu każdego zdarzenia, wpisać jakie były wtedy otwarte połączenia, jakie pliki, jakie uruchomione procesy. Możecie śledzić nie tylko zdarzenia w kolejności, ale także stan systemu na kolejnych etapach.

 

Pułapki

Tak Wam sprzedaję tego Sysdiga, ale muszę przyznać jest w nim też parę pułapek. Nie jest to coś, czego się należy bać, ale warto mieć na uwadze. Po pierwsze version 0.1.91… Z takimi numerami wersji, to wiadomo, że można się spodziewać wszystkiego. Jest jeszcze całkiem sporo syscalli. które nie są zaimplementowane. Możecie zobaczyć tylko, że wystąpiły. Nie zobaczycie żadnych argumentów. To utrudnia śledzenie. Raz zdarzyło mi się, że Sysdig wywalił proces. Oczywiście był to produkcyjny postgres, bo cóżby innego. Po zgłoszeniu chłopaki naprawili to od ręki i od tamtej pory nie miałem najmniejszych problemów ze stabilnością Sysdiga. Jedyne co mi się udało znaleźć, to jakiś błąd w komponencie usercase’owym. Utrudniał użycie, ale nie wywalał całej maszyny.

 

Jeżeli używacie kontenerów czy PID namespaces to pamiętajcie, że Sysdig ich nie wspiera. Zawsze pokazuje PIDy tak, jak występują w głównym PID namespace. Jeżeli chcecie uruchomić go np. wewnątrz kontenera to wszystkie PIDy będą złe. Natomiast i tak, w tym aspekcie Sysdig zachowuje się dużo lepiej niż strace, który obsługuje PID namespaces do połowy. W momencie, kiedy pojawia się nowy proces i strace chce się do niego podpiąć, to jest zwracany PID, taki, jaki go widzi proces w środku, natomiast strace się podpina po tym PIDzie na zewnątrz. Jeżeli więc jest to jakiś świeżo uruchomiony namespace, gdzie PIDy są jeszcze niskie, to z reguły Strace się próbuje podpiąć w jakiś wątek jądra i się wywala. Całkowity brak wsparcia dla namespaces działa więc w tym przypadku na korzyść Sysdiga. Nie robi, ale przynajmniej nie szkodzi.
Kolejna mniej przyjemna rzecz to także fakt, że Sysdig wymaga praw do dostępu. O ile strace’a możecie sobie uruchomić jako nieuprzywilejowany user na swoich własnych procesach, o tyle z Sysdigiem już tak łatwo nie ma. Pozwala na śledzenie całego systemu, więc potrzebuje odpowiednio wyższych uprawnień.

 Grzegorz Nosek

Od momentu, kiedy powstał ten tekst, sysdig mocno się rozwinął. W wersji 0.1.101 jest dużo więcej filtrów, dłutek i obsługiwanych syscalli, poprawnie współpracuje z kontenerami i PID namespaces a dodatkowo dorobił się świetnego trybu interaktywnego (csysdig), w którym można zagłębić się zarówno w zakamarki systemu, jak i możliwości samego sysdiga.