W tej części cyklu zajmiemy się diagnostyką wolnych stron webowych. Będzie to niejako podsumowanie cyklu, bo skorzystamy tu z technik, które omawiałem w poprzednich częściach.

Diagnostyka aplikacji webowych – wprowadzenie
Na początek kilka prostych wiresharkowych trików, które pozwolą ci na szybką ocenę sytuacji bez nadmiernego wgłębiania się w analizowanego dumpa.
Najprostszy filtr, który pozwala na szybką identyfikację ruchu HTTP i porównanie zawartości dumpa z tym, co widać po stronie przeglądarki, to:

http contains GET

Pamiętaj, żeby zachować wielkość liter. Nie pytaj mnie, dlaczego. To ważne, widocznie filtry Wiresharka są case-sensitive. Mój przykładowy dump, po zastosowaniu tego filtra pokazuje poniższą listę.

Później możesz sobie porównać listę z Wiresharka z listą poleceń GET złapaną z poziomu przeglądarki za pomocą Developer Tools. Ale do tego jeszcze wrócimy.
Przy analizie protokołu HTTP bardzo przydaje się dobrze ukryta, ale niezwykle przydatna funkcja Wiresharka, która wylicza czasy w konwersacjach TCP. Domyślnie jest wyłączona, ale my będziemy jej potrzebować w dalszych zastosowaniach. Możesz ją włączyć na dwa sposoby: albo z poziomu głównego menu, albo z poziomu menu kontekstowego w dumpie. Oba i tak prowadzą do tego samego okna.
Na dowolnym pakiecie TCP otwórz menu kontekstowe (prawy klawisz myszy) i wybierz opcję, jak poniżej.

Ważne są zaznaczone opcje.

Relative sequence numbers pewnie i tak masz włączoną, ale należy ci się szybkie wyjaśnienie. Numery sekwencyjne w pakietach nie są identyczne z tymi, które widzisz w dumpie, ale włączenie tej opcji powoduje, że liczone są od 1, co jest łatwiejsze do interpretacji.
Czasami Wireshark nie widzi albo po prostu nie ma tej informacji w pakietach, jaki jest współczynnik skalowania TCP Window. Żeby uniknąć sytuacji, w których wyznaczenie rozmiaru TCP Window jest niemożliwe, można go poinstruować, żeby zawsze brał 256 (=28).
Track number of bytes in flight jest wymagająca i pamięciożerna, ale pozwala na ilustrację ilości danych, które jeszcze nie zostały potwierdzone pakietami ACK.
I na koniec najważniejsza, Calculate conversation timestamps. Dzięki tej opcji Wireshark wyznacza czas od pierwszego i poprzedzającego pakietu w ramach konwersacji TCP. Jaki jest efekt włączenia tych opcji?
Śledzenie Bytes in flight można włączyć jako dodatkową kolumnę w ogólnym widoku. Przejdź do edycji kolumn i dopisz nową, jak na obrazku poniżej.

Ta nowa kolumna nie musi być cały czas włączona w twoim profilu, ale raz zdefiniowana już tam jest. Ale teraz sprawdźmy, jak znaleźć wolne operacje HTTP w dumpie. Wykorzystamy do tego liczone przez Wiresharka timestampy, filtry i wykresy.

Wolne hity
Jeden prosty filtr pozwoli na znalezienie w dumpie wszystkich hitów, których czas odpowiedzi był dłuższy niż pewna wartość progowa. Przykładowo, chcesz wiedzieć, które operacje HTTP trwały dłużej niż 2 sekundy. W polu filtrów wpisz poniższą frazę:

http.time > 2

Warto ten filtr zapisać na przyszłość, np. pod nazwą Slow HTTP. Guziczek +, nazwa i gotowe!

Poniżej masz przykład wolnego hitu – tu akurat było to ładowanie obrazka GIF – gdzie widać efekt włączenia obliczania timestampów, czyli pomiar czasu request-response. Obrazek ładował się przez ponad 3,8 sekundy. Jak na dzisiejsze standardy, stanowczo za długo.

Ale pamiętaj, filtr Slow HTTP pokaże hity, a to nie są strony. Jeśli chcesz sprawdzić czas ładowania stron, lepiej skorzystaj z Developer Tools w swojej przeglądarce.

Ostatnia sztuczka z szybką analizą dumpa zawierającego ruch HTTP to statystyki.

http.response.code == 500 (lub 404, 407 itd.)

Wszystko powyżej to tylko proste sztuczki, ale bardzo przydatne podczas faktycznej analizy ruchu HTTP. Teraz przypomnij sobie nasze eksperymenty z Kibaną (część 6 cyklu „Elasticsearch na wczoraj”). Tam robiliśmy wizualizację to dla całej aplikacji na podstawie logu serwera webowego. Powyższy filtr pozwala na podobną analizę w kontekście pojedynczego klienta i poszczególnych hitów.
Musisz też pamiętać, że przeglądarkowe narzędzia Developer Tools są dużo bardziej atrakcyjne, ale mają pewną istotną cechę, która może w pewnych przypadkach okazać się wadą, a mianowicie, pokazują tylko aktywność związaną z ładowanymi stronami. Nie zobaczysz tam tego, co dzieje się obok w tym samym czasie na analizowanej maszynie, a co może mieć istotny wpływ na szybkość ładowania stron czy dostępność aplikacji. Wiadomo, każdy developer zacznie od Developer Tools, ale jeśli nie znajdzie tam odpowiedzi czy rozwiązania problemów, trzeba skorzystać z Wiresharka (czy innego analizatora ruchu sieciowego).

Analiza strony webowej
Wracamy do wolnych hitów. Powiedzmy, że w analizowanym dumpie znaleźliśmy hit, który ładował się dłużej niż 2 sekundy (bo użyliśmy filtra http.time > 2). Widać to na powyższym ekranie z Wiresharka. W Developer Tools też to łatwo znaleźć, bo w sekcji Network zobaczysz na wykresie waterfall te hity, które ładowały się znacząco wolniej niż pozostałe, np. taki:

Obrazek GIF ładował się przez ponad 3,8 sekundy i nic dziwnego, bo miał wielkość 2,2 MB. Od razu nasuwa się pytanie, czy dość kiepskiej jakości animowany GIF jest potrzebny na stronie startowej serwisu? Atrakcyjność można osiągnąć skuteczniejszymi metodami, o czym wiedzą doświadczeni projektanci stron i developerzy webowi. Sprawdźmy teraz, czy podczas ładowania strony były jakieś problemy ze strony sieci i/lub stosu TCP.

Jeśli pamiętasz, w poprzednich częściach wspominałem Expert Information. To najszybsza metoda na sprawdzenie, czy w dumpie są jakieś istotne problemy. Klikam kolorowy wskaźnik w lewym dolnym narożniku okna Wiresharka i mam podsumowanie całego dumpa.

Od razu widać, że idealnie nie jest, ale niekoniecznie to znaczy, że jest jakaś tragedia.
Czerwonym błędem nie warto się zajmować, bo to dość typowe w trakcie łapania dumpa, że coś się nie złapało; poza tym zdarzyło się tylko jeden raz. Spójrzmy na listę Warnings. Podobnie jak wyżej, dwa pierwsze przypadki typowe, ale już trzeci pokazuje nam, że coś złego się wydarzyło. TCP Window odbiorcy-klienta się zapełniło i warto to sprawdzić.
Dla uproszczenia analizy, odfiltruję z dumpa ruch inny niż pomiędzy moją przeglądarką a serwerem, na którym stoi analizowany website. W polu filtra wpisuję poniższą frazę:

ip.addr==188.128.134.33 && tcp.port==80

Tak przefiltrowanego dumpa zapiszę z nową nazwą, czyli File > Export Specified Packets, podaję nową nazwę i gotowe. W nowym, mniejszym dumpie sprawdzam ponownie Expert Information.

Po rozwinięciu tej sekcji klikam wskazany pakiet i dostaję dokładny widok.

Maszynie klienta potrzebna była 1,093 sekundy, żeby opróżnić bufor i poinformować serwer, że może wznowić odbiór danych. Skąd to wiadomo? Możesz czas 6,33 s odjąć od 7,42 albo ustawić czas referencyjny na pakiecie 3831 i sprawdzić czas pakietu 3837. Pakiety zaznaczone na czarno warto przeanalizować dokładniej. Po zapełnieniu TCP Window po stronie odbiornika, sygnalizowanego pakietem 3832 TCP Zero Window, serwer co jakiś czas odpytuje klienta pakietem Keep Alive czy może wznowić nadawanie. Pierwsze odpytanie przyszło po 333 ms (czas z kolumny Delta T). Kiedy klient odpowiedział „TCP Window zapełnione” w pakiecie 3834, serwer postanowił poczekać nieco dłużej z następnym pytaniem, bo 0,5 sekundy (pakiet 3835). Okno nadal było zerowe (pakiet 3836) i dopiero po 260 ms (pakiet 3837) stos TCP klienta powiadomił serwer, że coś drgnęło i można wznowić transmisję.
Ale co się działo po stronie przeglądarki, kiedy klient nieco nawalił? Łatwo to sprawdzić podwójnie klikając zaznaczony wiersz w dolnym panelu. To spowoduje, że pójdziemy do pakietu 5417.

Na górze widać, że to response HTTP 200 na żądanie przesłania jakiegoś obrazka GIF. A pakiet z requestem jest zaznaczony w dolnym panelu. Nie zostaje nic innego, jak double-click tym wierszu, żeby pójść do pakietu 933.

Sprawa wyjaśniona. Ten podejrzany wielki GIF ładował się wolno, bo klient nie dawał rady odbierać danych. Można to dodatkowo zilustrować na wykresie, co robiliśmy już wcześniej.

Kliknięcie na wykresie w znacznik, gdzie zielona linia schodzi do zera prowadzi do pakietu 3831, czyli tam, gdzie już przed chwilą byliśmy.
Ale czy to jedyny powód, dla którego ten obrazek tak wolno się ładował? I czy to jedyny problem w tym dumpie? Na pewno nie, co widać w Expert Information. Były pakiety oznaczone Out of Order, co oznacza, że pojawiły się w niewłaściwym momencie, np. za wcześnie albo zbyt późno i bufor sterownika karty sieciowej nie był w stanie zaliczyć go do właściwego segmentu.
Do analizy retransmisji możemy wykorzystać Expert Information, jako skondensowaną formę prezentacji problemów, albo przejść bezpośrednio do pakietów korzystając z filtra TCP Problems. Ja ten filtr zmodyfikowałem do poniższej postaci w celu zawężenia kontekstu do serwera WWW, na którym wystawiony jest website (wszystko w jednym wierszu):

ip.addr==188.128.134.33 && tcp.port==80 && tcp.analysis.flags && !tcp.analysis.window_update

Dodatkowo, w filtrze uwzględniłem odsiewanie wszystkich pakietów kontrolnych do modyfikacji TCP Window (do tego wrócimy).

Jak widać, trochę problemów było, głównie retransmisje. Pakiety z problemami stanowiły 2.8% wszystkich złapanych, co niezbyt dobrze świadczy o jakości sieci, ale nie można powiedzieć, że stratność wynosi 2.8%. Wiadomo, że istotny odsetek pakietów był przesłany przez stos TCP w ramach obsługi strat w sieci.

Co z tym można zrobić? Można sprawdzić, którego hitu w ramach strony dotyczą te retransmisje. I tu ciekawostka. Po nitce do kłębka, Wireshark pozwala na sprawdzenie, którego requestu dotyczą retransmisje. Wybrałem sobie przypadek, kiedy klient wysłał 40 duplikatów pakietu ACK i sprawdziłem, czego to dotyczyło.

Jak widać na obrazku, to powtórzenia pakietu ACK z numerem 1602. Zatem lecę do tego pakietu sprawdzić, jakiego requestu był potwierdzeniem. Kolejny obrazek pokazuje tę sytuację.

Jak widać w dolnym panelu, to było potwierdzenie segmentu z pakietu 1600 (ptaszek przy pakiecie 1600 w górny panelu). Zatem sprawdźmy, co to za segment tam się kończył.

Odpowiedź widać w dolnym panelu, gdzie mamy podany numer pakietu z responsem (poskładanym w wielu pakietów, bo nie mieścił się w jednym). Szybki skok do pakietu 5417 i mamy odpowiedź.

Na górze widać, że to response HTTP 200 na żądanie przesłania jakiegoś obrazka GIF. A pakiet z requestem jest zaznaczony w dolnym panelu. Nie zostaje nic innego, jak double-click tym wierszu, żeby pójść do pakietu 933.

I zagadka rozwiązana. Hit, do którego było tyle retransmisji (ta seria 40 pakietów nie była jedyna), to nic innego, jak wielki obrazek GIF, który wyłapaliśmy jako wolny na samym początku. Wniosek początkowy – zbyt duża wielkość pliku – okazał się nie do końca trafiony. Poza problemami po stronie klienta (Zero Window Size), również straty sieci, a w związku tym retransmisje, miały wpływ na czas ładowania się obrazka.

Wcześniej obiecałem wrócić do filtrowania. Pakiety kontrolne odpowiedzialne za sterowanie wielkością TCP Window niekoniecznie muszą być uznawane za problematyczne. To się normalnie zdarza, że TCP Window podlega modyfikacjom w trakcie transmisji. Jeśli więc chcesz wyłączyć te pakiety z filtra TCP Problems, dodaj do niego poniższą frazę:

!tcp.analysis.window_update

Wówczas taki filtr będzie wyglądał tak:

tcp.analysis.flags && !tcp.analysis.window_update

Taki filtr możesz mieć obok pierwszego TCP Problems, nic nie stoi na przeszkodzie.

I tak dobrnęliśmy do końca cyklu poświęconego Wiresharkowi jako narzędziu pomocnemu w analizie wydajności aplikacji. Jednak ten cykl nie wyczerpuje tematu. Obserwuj bloga Omnilogy, bo na pewno będziemy jeszcze omawiać ciekawe przypadki.
Masz pytania lub uwagi, skontaktuj się z nami.