Wszystkie zgłaszane przez klientów problemy traktujemy bardzo poważnie. Czasami pojawiają się zgłoszenia które, ponieważ mogą dotyczyć całej grupy naszych wtyczek, analizowane są przeze mnie. Zdecydowałem, że podzielę się tutaj jedną z moich analiz.
Jeden z naszych klientów zainstalował 17 naszych wtyczek oraz WPML, a następnie zmierzył czas odpowiedzi skryptu admin-ajax.php. Stwierdził, że największe spowolnienie spowodował WPML: o około 224%, ale na drugiej pozycji znalazł się pakiet 7 wtyczek ShopMagic, który spowodował spowolnienie o około 33%. Zaniepokoiliśmy się, ponieważ to dość znacząca różnica i postanowiliśmy to sprawdzić.
Odtworzenie problemu
Jako że test klienta opierał się na wysłaniu serii pojedynczych requestów do prostego skryptu admin-ajax.php i zmierzeniu czasu wykonania, w celu odtworzenia opisanego problemu zdecydowałem się na analogiczny test.
Testowa akcja
Najpierw dodałem prostą testową akcję:
I sprawdziłem czy WordPress zwraca spodziewany wynik.
curl -I http://wordpress.lh/wp-admin/admin-ajax.php?action=test
HTTP/1.1 200 OK Date: Thu, 26 Nov 2020 20:25:04 GMT Server: Apache/2.4.46 (Unix) PHP/7.4.10 TEST OK
Akcja testowa została dodana poprawnie.
Mierzenie czasu
Teraz należało zmierzyć średni czas odpowiedzi WordPressa. W tym celu użyłem prostego narzędzia ApacheBench dostarczanego razem z pakietem Apache HTTP Server. Zmierzyłem najpierw czas odpowiedzi WordPressa z WooCommerce, bez żadnych innych wtyczek.
Wysłałem 100 zapytań, jedno po drugim. Najczęściej podczas tego typu testów wysyłane jest wiele zapytań równolegle, ale zdecydowałem, że przeprowadzę testy analogiczne do zgłoszonych.
$ ab -n100 -c1 http://wordpress.lh/wp-admin/admin-ajax.php?action=test
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.0 0 0
Processing: 383 396 9.0 392 417
Waiting: 382 396 9.0 392 417
Total: 383 396 9.0 392 417
Średni czas odpowiedzi wyniósł 0,396 sekundy przy medianie 0,392 sekundy.
Następnie uruchomiłem 10 wtyczek pakietu ShopMagic, 7 dostępnych oraz trzy dodatkowe znajdujące się w fazie alfa.
Connection Times (ms)
min mean[+/-sd] median max
Processing: 476 525 128.0 495 1062
Waiting: 475 524 128.0 494 1062
Total: 476 525 128.0 495 1062
Wnioski
Różnica jest znacząca. Średni czas odpowiedzi wzrósł do 0,525 sekundy, a mediana do 0,495 sekundy, czyli o około 26%-37%. Problem zgłoszony przez klienta został potwiedzony.
Analiza grupowa
ShopMagic, podobnie jak wszystkie wtyczki WP Desk, wykonuje pewne standardowe akcje podczas każdego uruchomienia. Każda wtyczka sprawdza, czy wszystkie wymagania są spełnione i czy wtyczka może bezpiecznie się uruchomić. Testujemy wersję PHP, wersję WooCommerce, dostępne moduły PHP i wiele innych rzeczy. Pojedynczo te czynności nie zajmują wiele czasu, ale istnieje niebezpieczeństwo, że gdy wykona je 17 wtyczek, to łączny wpływ na czas pracy może być znaczący. Niebezpieczeństwo jest tym większe, że część z potrzebnych informacji trzeba pobrać z nagłówków innych wtyczek, a parsowanie tekstowych nagłówków jest dość czasochłonne.
Sprawdźmy to: usunąłem sprawdzanie wymagań we wszystkich wtyczkach i po raz kolejny wysłałem serię zapytań.
Connection Times (ms)
min mean[+/-sd] median max
Processing: 512 551 37.4 549 689
Waiting: 512 551 37.4 549 689
Total: 512 551 37.4 549 689
Nie widać znaczącej różnicy, więc na razie hipoteza, że problem jest rozproszony we wszystkich wtyczkach, raczej nie znalazła potwierdzenia.
Analiza z poziomu WordPress
Jednym z pierwszych kroków przy problemach z szybkością działania wtyczek jest odwołanie się do jednego z WordPressowych profilerów. Moim ulubionym jest QueryMonitor.
Analiza zapytań
Miejscem, gdzie często powstaje najwięcej opóźnień, jest baza danych. Bardzo łatwo jest napisać nieoptymalne zapytanie albo wysłać setki małych zapytań, których łączny narzut zamuli każdy sklep.
Widać, że najbardziej czasochłonne są zapytania dotyczące opcji. Na drugiej pozycji znalazł się Action Scheduler, czyli komponent będący częścią WooCommerce, a służący do kolejkowania zdarzeń. Nie widać żadnych zapytań ze wtyczki, które znacząco wpłynęłyby na czas ładowania.
Dlaczego tyle czasu zajmuje obsługa opcji? WordPress wszystkie dane zapisywane w cache domyślnie trzyma w tabeli opcji, przy czym każdy transient to dwa oddzielne rekordy w bazie danych. Jest to jeden z powodów, dlaczego zawsze warto zainstalować cache, dzięki któremu wszystkie zapytania związane z danymi tymczasowymi trafią do serwera wyspecjalizowanego w cache takiego jak Redis.
Tutaj znajdują się zapytania, za które odpowiada ShopMagic. Niestety nie możemy ich bardziej zoptymalizować i oba są konieczne. Testowany sklep ma dodanych 36 różnych automatyzacji i trzeba zawsze pobrać je wszystkie, wraz z ich danymi, i zainicjalizować. Tylko wtedy ShopMagic wie, na jakie zdarzenia ma zareagować podczas trwania wywołania.
Znaleźliśmy zatem element, który odpowiada za część opóźnienia. Niestety nie ma tutaj miejsca na optymalizację.
Analiza pozostałych wskaźników Query Monitor
Poza zapytaniami do bazy Query Monitor pokazuje też szereg innych przydatnych informacji.
Często najbardziej czasochłonną operacją są odwołania sklepu do zasobów zewnętrznych HTTP API calls. W tym przypadku nie ma takich odwołań.
Warto sprawdzić też zakładkę Transient updates. Czasami wtyczki nadużywają mechanizmu danych tymczasowych/transientów, a ponieważ domyślnie transienty trzymane są w bazie danych, potrafi to bardzo opóźnić działanie strony.
Analiza za pomocą niskopoziomowego profilera
Baza danych odpowiada za część opóźnień, ale to nie wystarczy, żeby wytłumaczyć tak dużą różnicę w czasie ładowania. Może po prostu w kodzie wtyczki istnieją miejsca, które wykonują jakieś wyjątkowo czasochłonne operacje?
XDebug jest najczęściej używanym przez developerów PHP debuggerem. Oprócz typowego debugowania potrafi również profilować kod i, po prześledzeniu każdej linii, stworzyć raport, który pozwoli na analizę czasu wykonania linia po linii. Raport utworzony przez XDebug tworzony jest w postaci dość wymagającej dla czytelnika, dlatego wykorzystam program QCacheGrind do jego dalszej analizy.
Polecenia posortowane łącznym czasem wywołania pokazują, w których miejscach najwięcej czasu przecieka nam przez palce. To, co przede wszystkim rzuca się w oczy to fakt, że łącznie ponad 50% czasu procesor spędza na wykonywaniu poleceń load_textdomain oraz różne odwołania do funkcji związanych z tłumaczeniami. Composer\Autoload to proces, który ładuje kolejne pliki PHP do parsowania. Widać także WooCommerce zjadające ok. 20% oraz wtyczkę do logowania emaili, która też jest uruchomiona w sklepie testowym.
Ponieważ wszystkie wtyczki z pakietu mają te same przedrostki w klasach, łatwo można przefiltrować wywołania pod kątem wtyczek ShopMagic. Najdłużej wykonywane polecenie get_build_in_events jest konieczne dla poprawnego działania wtyczki, a po rozbiciu na szczegóły pokazuje, że najwięcej czasu zajmuje samo załadowanie plików z kodem: Class Autoloader.
Weryfikacja hipotez
Na podstawie zebranych danych możemy przetestować, jak zachowa się pakiet wtyczek, gdy wprowadzimy modyfikacje we wtyczce głównej ShopMagic.
Aktywny tylko WooCommerce
Connection Times (ms)
min mean[+/-sd] median max
Processing: 383 396 9.0 392 417
Waiting: 382 396 9.0 392 417
Total: 383 396 9.0 392 417
Średnia 396 ms.
Uruchomione wszystkie wtyczki pakietu ShopMagic oraz WooCommerce
Connection Times (ms)
min mean[+/-sd] median max
Processing: 476 525 128.0 495 1062
Waiting: 475 524 128.0 494 1062
Total: 476 525 128.0 495 1062
Średnia 525 ms.
Pakiet ShopMagic i WooCommerce, ale wtyczki ShopMagic nie ładują swoich tłumaczeń
Connection Times (ms)
min mean[+/-sd] median max
Processing: 457 484 25.6 471 536
Waiting: 457 484 25.6 471 536
Total: 457 484 25.6 471 536
Średnia 484 ms.
Widać bardzo znaczącą poprawę; niestety nie możemy zrezygnować z tłumaczeń.
Pakiet ShopMagic i WooCommerce bez tłumaczeń oraz bez sprawdzania wymagań
Connection Times (ms)
min mean[+/-sd] median max
Processing: 444 483 89.1 457 849
Waiting: 444 483 89.1 457 848
Total: 444 483 89.1 457 849
Średnia 483 ms.
Sprawdzanie wymagań (PHP, wersji wtyczki głównej, kompatybilności itp.) nie wpływa w znaczący sposób na szybkość działania.
Po zakomentowaniu linii, która pobiera automatyzacje i buduje automatyzacje
Connection Times (ms)
min mean[+/-sd] median max
Processing: 363 393 52.9 375 700
Waiting: 363 393 52.9 375 700
Total: 363 393 52.9 375 700
Średnia 393 ms.
W tym momencie zbliżyliśmy się do czasu ładowania samego WooCommerce. Problem jednak w tym, że wtyczka nie nasłuchuje już żadnych zdarzeń. Wtyczka oprócz tego nadal robi szereg ważnych rzeczy, ale — jak widać — nie mają one większego znaczenia dla szybkości działania sklepu. Niestety nie możemy usunąć głównej funkcjonalności (to tam wysyłamy zapytanie do bazy), ale ten test pokazał, że poza nią wtyczki praktycznie nie obciążają sklepu.
Niekończąca się praca
Czy to oznacza, że nie udało się znaleźć żadnych elementów wymagających optymalizacji? Nie. Przy okazji tej analizy znalazłem szereg niewymienionych mniej istotnych elementów, które warto było poddać optymalizacji.
Cześć z nich została zmodyfikowana od razu, część dodana do @TODO. Niestety nie udało się znaleźć żadnych elementów, które odpowiadałyby za spowolnienie i których optymalizacja w znaczący sposób wpłynęłaby na szybkość działania sklepu.
Przykładowo, podczas analizy QCacheGrind odkryłem, że metoda get_event_list wywoływana była bardzo często, więc dodaliśmy cache, który o około 1% polepszył czas działania wtyczki. Niestety zmiany nie były na tyle duże, żeby były widoczne w testach.
Odkryłem też, że wtyczka przez pomyłkę ładowała swoje tłumaczenia dwukrotnie. Niemniej WordPress sprawdza, czy plik tłumaczeń był już ładowany, więc wyeliminowanie problemu nie przyspieszyło w żaden sposób wtyczki, a jedyne wpłynęło na licznik uruchomień pokazywany w profilerze.
Udało się też częściowo obalić tezę, że sama liczba zainstalowanych wtyczek w WordPress ma znaczenie. Okazuje się, że znacznie większe znaczenie ma łączna ilość tłumaczonego tekstu we wtyczkach. Być może autorzy wtyczek powinni rozważyć kompilowanie wtyczki pod konkretną wersję językową?
Czy to oznacza, że praca przy optymalizacji wtyczek została zakończona? Nie. Ta praca wciąż trwa i ciągle będzie trwała. Dodajemy nowe funkcjonalności, poprawiamy błędy i stale rozwijamy wtyczki, a każda nowa linia kodu zmusza nas do dalszych optymalizacji i ulepszeń.
