Permanentna inwigilacja w Erlang VM
Istnieją takie paradygmaty i języki programowania, w których klasyczne podejście do debugowania nie ma zbyt wiele sensu. W ramach alternatywy, takie środowiska udostępniają własne mechanizmy, aby ułatwić taki proces. Jednym z takich środowisk jest Erlang, który słynie z mechanizmu śledzenia procesów (ang. tracing). Rzekomo możemy widzieć każdą akcję i zdarzenie, które zachodzi wewnątrz maszyny wirtualnej. No właśnie — czy aby na pewno wszystkie? Odpowiedź na to pytanie, jak i samo wyjaśnienie czym jest mechanizm śledzenia procesów znajduje się w poniższym artykule.
Wojciech Gawroński. Co-founder, Solutions Architect and Engineer w Pattern Match. Pasjonat IT. Głęboko przekonany, że to IT powinno służyć biznesowi a nie odwrotnie — co realizuje w firmie Pattern Match. Pomimo pragmatycznego nastawienia, posiada swoje ulubione technologie i dziedziny — obraca się wokół tematów związanych z Erlangiem/Elixirem, DevOps oraz Infrastructure as a code a także zagadnień związanych z chmurą (szczególnie AWS).
Spis treści
Współbieżność wszystko komplikuje…
Pozwólcie, że zacznę od historii. Po wdrożeniu na produkcję nowej wersji oprogramowania na całej flocie maszyn w czterech różnych regionach świata, wszystko wyglądało w porządku. Po obserwacji metryk oraz sprawdzeniu logów nie znaleźliśmy nic, co mogłoby wskazywać na jakikolwiek problem. Odtrąbiliśmy sukces i zabraliśmy się za kolejne zadania.
Dwa dni później otrzymaliśmy zgłoszenie z działu obsługi klienta do zbadania. Jeden ze zintegrowanych partnerów skarży się na dużą ilość błędów zwracanych z naszego API, w dwóch różnych centrach danych. Zbadaliśmy metryki dla tego konkretnego partnera — wyglądały w porządku, ilość błędów — faktycznie większa, jednak dalej znajdowała się w przyjętej przez nas normie. Po krótkiej wymianie zdań, dotarliśmy do kolejnej wskazówki — odkryliśmy, że faktycznie API w pewnych przypadkach zamiast odpowiedzieć, wyrzucało błąd. Działo się to na tyle rzadko, że nie aktywowało żadnego z alarmów. Po zebraniu wszystkich faktów, postanowiliśmy zbadać ten problem na żywym organizmie.
Zatrzymajmy się na chwilę i pomyślmy co normalnie robi się w takiej sytuacji. Najpewniej obniżamy poziom błędów tak, aby większość akcji zapisywać do logów aplikacji. Potem tylko mozolne czesanie i być może znajdziemy przyczynę. Możemy podmienić wersję aplikacji, która posiada dodatkowe punkty instrumentacji, nowe metryki, przy odrobinie odwagi może nawet spróbujemy podpiąć się nieśmiertelnym `gdb` do żyjącej aplikacji.
Postąpiliśmy inaczej i skorzystaliśmy z tego, co daje nam maszyna wirtualna. Włączyliśmy mechanizm śledzenia procesów i zdarzeń dla tego konkretnego komponentu. I co się okazało? Bez większego wysiłku, produkcyjna maszyna i aplikacja wraz z włączonym podsystemem do debugowania były w stanie przetwarzać ruch z produkcyjnego środowiska. Kilkaset transakcji na sekundę. To przypominało diagnozowanie problemów z samochodem na autostradzie. Z tą różnicą, że mogliśmy bezpiecznie patrzeć pod maskę pędzącego samochodu nie mając żadnego kursu kaskaderskiego za sobą.
Po ustawieniu kilku punktów śledzenia i oczekiwaniu na ponowne wystąpienie sytuacji znaleźliśmy tą konkretną ścieżkę wykonania. Winę za problemy wewnątrz aplikacji ponosiła zewnętrzna biblioteka, klient HTTP, który oczekiwał, że po otrzymaniu statusu 204 (No Content) serwer nie odsyła żadnego bajtu w odpowiedzi. Oczekiwania nie zawsze zostają spełnione, więc i klient nie będąc na to przygotowanym wyrzucał wyjątek. To ciekawy problem, polecam sprawdzić jak zachowuje się wasz klient, tylko nie sprawdzajcie tego na produkcyjnej instancji, no chyba, że korzystacie z Erlanga.
Czym jest śledzenie procesów?
Część z was pewnie nie wierzy w powyższą opowieść. Takie środowisko, gdzie bez konsekwencji można włączyć tryb debugowania nie istnieje. Spójrzcie jednak na to z innej strony — przy całkowicie współbieżnym modelu pracy nie mamy innej opcji, świat nie poczeka na nas, aż skorzystamy z breakpointa. Osoby, które próbowały namierzyć problem klasycznym debuggerem w wielowątkowym środowisku wiedzą o czym mówię.
Tylko, że takie środowisko istnieje — wewnątrz maszyny wirtualnej Erlanga, zwanej bardzo często jako BEAM mamy do dyspozycji taki mechanizm, zwany śledzeniem procesów. Na poziomie środowiska uruchomieniowego możemy włączyć i wyłączyć generowania pewnych zdarzeń, które są wystawione z poziomu VM. Przykładem takich wywołań są wywołania funkcji, wysłanie wiadomości do innego procesu, stworzenie nowego procesu oraz odśmiecanie pamięci. Wszystko to na wyciągnięcie ręki, z pełną mocą języka programowania oraz zdalnej konsoli.
1> redbug:start("module:function->return").
{156,1}
2> module:function().
% 12:13:10 <0.42.0>({erlang,apply,4})
% module:function(some, parameters)
% 12:13:10 <0.42.0>({erlang,apply,4})
% module:function/2 -> ok
ok
3>
Innymi słowy: mamy do dyspozycji w każdej aplikacji zewnętrzny komponent, który generuje strumień zdarzeń, historię akcji z wykonania naszej aplikacji do konkretnego odbiorcy.
Przypomina to obserwowanie układu elektronicznego mając do dyspozycji różnego rodzaju próbniki, narzędzia (np. multimetr lub oscyloskop). W większości przypadków narzut tych narzędzi jest pomijalny i nie wpływa na obiekt obserwacji. Oczywiście, w przypadku błędu operatora, może dojść do małej katastrofy, ale czynnika ludzkiego nie możemy tutaj uniknąć.
Dlaczego w ogóle istnieje śledzenie procesów?
Część z Was na pewno zastanawia się, co kierowało twórcami maszyny wirtualnej, aby dodać taką funkcjonalność na poziomie maszyny wirtualnej. Odpowiedź na to pytanie jest szalenie ciekawa i warto się nad tym zastanowić.
Ponad 30 lat temu, kiedy Ericsson zainwestował czas i pieniądze w stworzenie Erlanga potrzebowali oni platformy, którą będzie można zdalnie debugować. Dlaczego? Ponieważ znali biznes telekomunikacji od podszewki i wiedzieli, że wszystkich problemów nie da się uniknąć, ani tym bardziej przewidzieć. A nie można odciąć ludzi od dostępu do telefonu, zwłaszcza jeśli chodzi o tak krytyczną infrastrukturę jak połączenia alarmowe.
Tworząc nowy język programowania oraz wirtualną maszynę udało im się spełnić to założenie. Jedno z najważniejszych dla nich w dawnych czasach. Współbieżna obsługa połączeń telefonicznych w switchu telefonicznym to niełatwe zadanie, dlatego zainwestowano więcej czasu w wbudowanie obsługi współbieżności. Centrala telefoniczna to idealny przykład modelu aktorowego i Erlang VM wewnętrznie czerpie z tego paradygmatu. To jednak temat na osobny artykuł.
Jeśli spojrzymy na wymagania firm telekomunikacyjnych 30 lat temu oraz nasze obecne wymagania jeśli chodzi o systemy informatyczne widzimy same podobieństwa. Wiele z nich, nawet jeśli nie są one tak krytyczne jak połączenia alarmowe, musi działać 24/7 z jak najmniejszym przestojem. Mimo tych wymagań i upływu lat, w dalszym ciągu chcemy mieć możliwość debugowania w czasie rzeczywistym jeśli coś pójdzie nie tak. I na pewno nie muszę wam tłumaczyć z jak skomplikowanymi systemami musimy sobie radzić.
Permanentna inwigilacja
Śledzenie procesów może być nieocenionym narzędziem. Szczególnie w sytuacji podbramkowej na produkcji, ale także i w codziennym programowaniu, kiedy próbujemy wyśledzić własne błędy już na pierwszym etapie testów naszej implementacji.
Po pierwszej fazie zauroczenia nowym narzędziem, każdy prawdziwy inżynier zaczyna pytania. To dobrze, bo ciekawość to jeden z głównych czynników, który pcha nas do rozwoju. To przytrafiło się również mnie, podczas jednego z warsztatów ElixirConf, które miałem przyjemność prowadzić w 2017 roku, ktoś zapytał: “Czy można śledzić wszystko i wszystkich?”.
Prosta i natychmiastowa odpowiedź brzmi: w zasadzie tak. Jednak jej wytłumaczenie nie jest już takie proste.
Co można, a czego nie wolno śledzić?
Z perspektywy doświadczonego Erlangowca, odpowiedź jest prosta — można śledzić prawie wszystko, a czego dokładnie nie wolno powiemy sobie za chwilę. Ale zanim dojdziemy do tego momentu chciałbym zrobić krok wstecz i zmienić punkt widzenia.
Ponieważ to pytanie pojawiło się na ElixirConf natychmiast odpowiedziałem “tak, ale …” ponieważ byłem przygotowany na inny wariant tego samego pytania. Jeden z powodów, dla których lubimy Elixir (młodszy brat, język programowania działający na maszynie wirtualnej Erlanga) są higieniczne makra. Są one tak nazwane ponieważ bazują na składni i AST oraz ich transformacjach. Dają one ogromne możliwości, ale nie ma nic za darmo.
Makra Elixira
Makra znikają na etapie kompilacji. To wydaje się oczywiste, jeśli się nad tym zastanowić, ale jako konsekwencja, razem z nimi znikają widoczne miejsca, w których możemy zaczepić się w celu śledzenia zdarzeń. Mówiąc fachowym językiem — nie jesteśmy w stanie zapisać wzorca śledzenia (ang. trace pattern) bazując tylko na kodzie źródłowym, musimy znać rozwinięcie makra.
Wiele bibliotek (tych najważniejszych i najpopularniejszych) bardzo mocno wykorzystuje makra, co powoduje, że ich śledzenie jest odrobinę trudniejsze. Jest to możliwe, ponieważ makra rozwijane są i tak do kodu źródłowego, a więc znając ich rozwinięcie, możemy śledzić ten kod.
Zainteresowani tą funkcjonalności powinni szukać wskazówek w dokumentacji modułu `Macro`, szczególnie jeśli chodzi o funkcję `expand_once/2`:
iex> h Macro.expand/2 iex> h Macro.expand_once/2
Ożeż Ty, Kompilatorze!
Jest jeszcze jedno miejsce, gdzie Elixir może nam przeszkadzać w śledzeniu. Dla niektórych funkcji kompilator przepisuje ich wykonanie lub rozwija je, zastępując wywołanie funkcji jej ciałem. W wielu przypadkach dotyczy to popularnych funkcji bibliotecznych, które są lekkimi opakowaniami biblioteki standardowej Erlanga lub Elixira. Dlaczego wspomniałem o dwóch mechanizmach?
Ponieważ, na ten moment są dostępne dwa mechanizmy rozwijania: automatyczne przepisanie na poziomie kompilatora, oraz na poziomie adnotacji w module Elixirowym. Jeśli chodzi o ten drugi przykład (adnotacje), bardzo dobrym przybliżeniem takiego rodzaju rozwinięcia jest przepisanie kodu 1:1 — w zasadzie na bazie zastąpieniu jednego tekstu innym, nie ma tutaj miejsca na bardziej skomplikowane modyfikacje np. zmianę kolejności czy konwersję argumentów.
Innym przykładem jest automatyczne przepisanie zaimplementowane w logice kompilatora. Służy do tego osobny moduł `elixir_rewrite`. To bardziej zaawansowane narzędzie, które pozwala na bardziej skomplikowane transformacje. Przykładem takiej funkcji jest `String.to_integer/1`:
inline(?string, to_integer, 2) -> {erlang, binary_to_integer};
@doc """
Returns an integer whose text representation is `string`.
Inlined by the compiler.
## Examples
iex> String.to_integer("123")
123
"""
@spec to_integer(String.t()) :: integer
def to_integer(string) do
:erlang.binary_to_integer(string)
end
Nie można śledzić tej funkcji, ponieważ kompilator zastępuje ją wywołaniem funkcji Erlangowej `:erlang.binary_to_integer/1`.
Jeśli chodzi o rozwijanie za pomocą adnotacji, listę funkcji, które z tego korzystają możesz odnaleźć za pomocą następującego zapytania w serwisie Github.
Czyli w Erlangu mogę wszystko?
Omówiliśmy czego nie można śledzić w Elixirze. Czy to oznacza, że w Erlangowej aplikacji nie ma podobnych ograniczeń? Nie tak szybko!
Spójrzmy najpierw w jaki sposób w Erlangu zapisujemy wzorzec co mamy śledzić.
Poboczna uwaga: nie byłbym sobą, gdybym nie wspomniał, że część narzędzi korzystających ze śledzenia nie traktuje Erlangowych rekordów równoprawnie z innymi strukturami danych. Zamiast tego musimy korzystać z zapisu rekordu jako krótki. Więc twórcy `redbug` jeśli to czytacie — stworzyliście świetne narzędzie, ale potrzebujemy rekordów.
Kto śledzi śledzącego?
Spróbujmy zastanowić się skąd maszyna wirtualna wie skąd i jakie zdarzenia powinna przechwytywać?
Jako pierwszy krok, tworzony jest nowy proces nazwany tracer. Taki proces otrzymuje zdarzenia do swojej skrzynki wiadomości na bazie filtra, który definiujemy. Ponieważ mamy do dyspozycji pełen język programowania, oznacza to, że przetwarzanie zdarzeń może być oparte o dowolne transformacje.
Taki filtr (zwany wzorcem śledzenia, ang. tracer pattern) po stworzeniu jest przekazywany aż do procesu tracera. Definicja filtru jest oparta o język domenowy, który jest podzbiorem Erlangowych struktur danych. Na bazie tego zapisu i języka domenowego mówimy maszynie wirtualnej jakie zdarzenia powinna obserwować.
W tym opisie znajdują się dwie wskazówki, czego nie możemy śledzić. Pierwsza z nich, to wbudowane funkcje Erlangowe (tzw. BIF, built-in functions) np. ta służąca do włączenia procesu śledzenia. Druga wskazówka ukryta jest w definicji języka domenowego. Skoro, możemy te zdarzenia filtrować, agregować i porównywać, to czy możemy śledzić również te operacje.
Jesteśmy coraz bliżej, dlatego pora na eksperyment.
BEAM me up, Scotty!
Możemy zweryfikować obie hipotezy prostymi eksperymentami. Spróbujemy zbudować wzorzec, który śledzi tylko jedną funkcję i zobaczymy, czy mamy co śledzić:
erl> erlang:trace_pattern({erlang, is_binary, 1}, true).
0
erl> erlang:trace_pattern({erlang, hd, 1}, true).
0
erl> erlang:trace_pattern({erlang, apply, 3}, true).
1
erl> erlang:trace_pattern({lists, reverse, 1}, true).
1
Zero oznacza, że nie udało się znaleźć, żadnej funkcji pasującej do wzorca w maszynie wirtualnej. Część BIFów, można śledzić (dwa ostatnie przykłady) a część nie (dwa pierwsze przykłady). To samo dotyczy NIFów (ang. native implemented functions, funkcje zaimplementowane w języku C np. w celu optymalizacji) — wszystkie możemy śledzić, a BIFy to szczególny przypadek natywnej funkcji – więc ta hipoteza wydaje się częściowo prawdziwa i pokazuje na inny ważny element.
Jeśli sięgniemy jeszcze głębiej i sprawdzimy, których BIFów nie można śledzić, otrzymamy dość nieprzypadkową listę:
`'*'/2, '+'/1, '+'/2, '-'/1, '-'/2, '/'/2, '/='/2, '<'/2, '=/='/2, '=:='/2, '=<'/2, '=='/2, '>'/2, '>='/2, abs/1, 'and'/2, 'band'/2, binary_part/2, binary_part/3, bit_size/1, 'bnot'/1, 'bor'/2, 'bsl'/2, 'bsr'/2, 'bxor'/2, byte_size/1, 'div'/2, element/2, float/1, hd/1, is_atom/1, is_binary/1, is_bitstring/1, is_boolean/1, is_float/1, is_function/1, is_function/2, is_integer/1, is_list/1, is_number/1, is_pid/1, is_port/1, is_record/2, is_record/3, is_reference/1, is_tuple/1, length/1, node/0, node/1, 'not'/1, 'or'/2, 'rem'/2, round/1, self/0, size/1, tl/1, trunc/1, tuple_size/1, 'xor'/2`
Prawie przypomina ona listę funkcji, których możemy używać do zapisu wzorców śledzenia. Prawie, ponieważ wzorce śledzenia nie wspierają `binary_part/2` oraz `binary_part/3`. Dwie ostatnie jednak są wspierane w tzw. guard clauses ponieważ możemy tam dopasowywać wzorce bazując na binarkach. Mając przeczucie, że jestem blisko rozwiązania zagadki nie poddałem się i wskoczyłem wprost do kodu maszyny wirtualnej.
Prawda okazała się jeszcze bardziej skomplikowana:
%%
%% NOTE: All guard_bif(), arith_op(), bool_op() and comp_op() must be
%% defined in bif.tab as 'ubif', i.e bif without trace wrapper.
%%
%% Why?
%%
%% Because the compiler uses an optimized instruction for
%% the call to these bifs, which when loaded gets a direct
%% entry pointer inserted into itself by the loader,
%% instead of a bif table index as for regular bifs.
%%
%% If tracing is enabled on these bifs, when a module is loaded,
%% the direct entry pointer inserted into the call instruction
%% will be pointing to the trace wrapper, so even if tracing is
%% disabled for bifs, the loaded module will call these bifs through
%% the trace wrappers.
%%
%% The call instruction in question does not give enough information
%% to call trace match function {caller} for it to succeed
%% other then by chance, and the 'return_to' trace flag works just
%% as bad, so both will mostly say that the caller is 'undefined'.
%% Furthermore the calls to these bifs will still generate
%% trace messages from the loaded module even if tracing is disabled
%% for them, and no one knows what else might be messed up.
%%
%% That's why!
%%
ubif erlang:'and'/2 ubif erlang:'or'/2 ubif erlang:'xor'/2 ubif erlang:'not'/1 ubif erlang:'>'/2 sgt_2 ubif erlang:'>='/2 sge_2 ubif erlang:'<'/2 slt_2 ubif erlang:'=<'/2 sle_2 ubif erlang:'=:='/2 seq_2 ubif erlang:'=='/2 seqeq_2 ubif erlang:'=/='/2 sneq_2 ubif erlang:'/='/2 sneqeq_2 ubif erlang:'+'/2 splus_2 ubif erlang:'-'/2 sminus_2 ubif erlang:'*'/2 stimes_2 ubif erlang:'/'/2 div_2 ubif erlang:'div'/2 intdiv_2 ubif erlang:'rem'/2 ubif erlang:'bor'/2 ubif erlang:'band'/2 ubif erlang:'bxor'/2 ubif erlang:'bsl'/2 ubif erlang:'bsr'/2 ubif erlang:'bnot'/1 ubif erlang:'-'/1 sminus_1 ubif erlang:'+'/1 splus_1
/*
** OK, now for the bif's
*/
for (i = 0; i < BIF_SIZE; ++i) {
Export *ep = bif_export[i];
if (!ExportIsBuiltIn(ep)) {
continue;
}
if (bif_table[i].f == bif_table[i].traced) {
/* Trace wrapper same as regular function - untraceable */
continue;
}
Po odnalezieniu tych trzech miejsc wewnątrz kodu źródłowego Erlang VM okazało się, że kompilator Erlanga rozwija wspomniane funkcje. Przez rozwinięcie jednak rozumiemy tutaj dużo bardziej skomplikowaną optymalizację — ponieważ usuwany jest ich kontekst wykonania. Jako konsekwencja nie możemy ich śledzić. Dlaczego? Ponieważ w momencie uruchomienia śledzenia, maszyna wirtualna sięga do kontekstu wykonania konkretnej funkcji aby pobrać metadane. Z powodu braku kontekstu dla tych metod, nie jest możliwe śledzenie ich wykonania. Dla wszystkich innych funkcji maszyna wirtualna dostarcza wszelkie niezbędne dane.
Taki kontekst wykonania w maszynie wirtualnej BEAM nosi nazwę trace wrapper. I to ten element dostarcza danych do podsystemu śledzenia. Tak jak widać na wycinkach kodu, funkcje wspierane przez język wzorców śledzenia nie tworzą punktów trace wrapper a więc nie jest możliwe śledzenie takiej funkcji.
Dlaczego? Tutaj niestety pozostają spekulacje. Jeden z komentarzy zostawia całkiem pożyteczna wskazówkę, że śledzenie jednej z funkcji, która mogła zostać wykorzystana w mechanizmie śledzenia mogłaby spowodować nieskończoną pętlę i konsekwencji przerwać pracę maszyny wirtualnej z powodu np. braku pamięci. Z drugiej strony filtrowanie tych funkcji w czasie rzeczywistym niepotrzebnie by komplikowało implementację i mogło wprowadzić narzut wydajnościowy.
Wiedząc z czego wewnętrznie korzysta mechanizm śledzenia, możemy rozszerzyć nasze pytanie o dodatkową sekcję: “Czego jeszcze nie możemy śledzić?”.
Okazuje się, że niewiele rzeczy pozostało. Brakującym elementem (który okazuje się oczywisty, jeśli się nad nim zastanowić) okazują się funkcje anonimowe. Korzystając z takich funkcji nie mamy się gdzie zaczepić w oczywisty sposób, dlatego jest to jeden z powodów, dla którego bardziej doświadczeni Erlangowcy korzystają z tej funkcjonalności z dużą ostrożnością.
Podsumowanie
Śledzenie procesów to moim zdaniem jedna z najważniejszych rzeczy, która jest dostępna na maszynie wirtualnej Erlanga. Jest ona na tyle wygodna, że zwyczajnie mi jej brakuje, kiedy zmieniam stos technologiczny.
Czy którekolwiek ograniczenia umniejszają znaczenia śledzeniu? W żadnym wypadku, to przypadki brzegowe, które będą rzadko używane. W większości przypadków problem istnieje w naszym kodzie, a tam już możemy śledzić wszystko.
I choć sama wiedza jak śledzenie działa wewnętrznie nie jest potrzebna do użytkowania tego narzędzia, to uważam, że znacznie podnosi ona świadomość i wpływa na sposób budowania aplikacji. A do tego, teraz ktoś zrobił za Ciebie research i od tej pory nie musisz tego robić indywidualnie. Owocnego śledzenia!
Artykuł został pierwotnie opublikowany na blogu pattern-match.com.
Podobne artykuły
Krytyczne spojrzenie na kod jest kluczowy dla jego skutecznej analizy. Jak analizować systemy legacy
Sieci neuronowe. PyTorch i praktyczny projekt od początku do końca
Od czego zacząć swoją przygodę w branży IT? Rozmowa z Jackiem Hrynczyszynem, Java Developerem
Kim jest Software Architect? Obowiązki, specjalizacje, kariera
Co nowego w Javie? Przegląd zmian, które przyniosło JDK 20
Efektywne zarządzanie Protocoll Buffers z “Buf”. Wszystko, co powinieneś wiedzieć
Czy Scala to wciąż dobry język dla programistów w 2023 roku?
