Testy wydajności i profilowanie aplikacji PHP - Kolos Wikikolos.math.uni.lodz.pl/~archive/Inne -...

www.phpsolmag.org2 PHP Solutions Nr 6/2006

Dla początkujących

www.phpsolmag.org 3PHP Solutions Nr 6/2006


Zwiększenie wydajności jest mo-żliwe dzięki optymalizacji ko-du. Problem w tym, że dzisiej-

sze aplikacje pisane w PHP rozro-sły się do takich rozmiarów, iż cięż-ko przejrzeć cały kod i poprawić jego efektywność. Znajdując wąskie gardło w systemie można je zoptymalizować i w miarę niewielkim kosztem podnieść wydajność całej witryny. W tym artyku-le pokażemy, jak testować wydajność zarówno całej aplikacji, jak i wybra-nych fragmentów kodu oraz jak iden-tyfikować te partie kodu, które są przy-czyną największego narzutu czaso-wego.

Testy wydajności z PEAR::BenchmarkBenchmark to pakiet z repozytorium PE-AR (http://pear.php.net) zawierający kla-sy umożliwiające testowanie wydajności i profilowanie kodu napisanego w PHP. Pakiet ten można zainstalować mając

Każda aplikacja – webowa czy dowolna inna charakteryzuje się określoną wydajnością. Cecha ta staje się szczególnie istotna w świecie aplikacji internetowych, z których korzystają czasem tysiące użytkowników...

uprawnienia administratora (środowisko Linux) poleceniem:

pear install benchmark

PEAR::Benchmark składa się z trzech klas: Benchmark _ Iterate, Benchmark _

Profiler i Benchmark _ Timer.

Benchmark_TimerBenchmark _ Timer to klasa pozwalają-ca nam mierzyć czas, jaki upłynął mię-dzy kolejnymi tzw. markerami. Markery to miejsca pomiaru czasu, które ustawia-

Testy wydajności i profilowanie aplikacji PHPŁukasz Witczak

W SIECI

1. http://pear.php.net/package/Benchmark – strona domowa pakietu PEAR::Benchmark

2. http://www.linuxjournal.com/article/7213 – artykuł o profilowaniu przy pomocy APD

3. http://wiki.cc/php/Apd– Wiki o APD

4. http://www.omniti.com/~george/talks/Profiling-phpworks-2004.pdf– PDF o profilowaniu aplikacji w PHP

Stopień trudności: lll

Co należy wiedzieć...Powinieneś znać podstawy programo-wania proceduralnego i obiektowego w PHP5.

Co obiecujemy...Pokażemy, jak testować wydajność ca-łej aplikacji oraz jej poszczególnych fragmentów i nauczymy, jak identyfiko-wać wąskie gardła każdego programu.

www.phpsolmag.org2 PHP Solutions Nr 6/2006


www.phpsolmag.org 3PHP Solutions Nr 6/2006


my wywołaniem metody setMarker(). Na Listingu 1 widzimy funkcję doSth(), któ-rej jedynym celem jest generowanie ob-ciążenia.

Aby użyć klasy Benchmark _ Tim-

er, musimy ją dołączyć do bieżące-go skryptu w sposób typowy dla klas PEAR (zakładamy, że include _ path wskazuje położenie repozytorium PE-AR na dysku lokalnym). Następnie wy-wołujemy konstruktor klasy Bench-

mark _ Timer. Jak już wiemy, zadaniem funkcji doSth() jest generowanie ob-ciążenia, co uzyskujemy poprzez wy-konywanie czasochłonnych operacji, takich jak tworzenie tablicy składają-cej się z 1000 elementów i jej sortowa-nie według kluczy w porządku odwrot-nym. Po utworzeniu tej funkji pozosta-je nam już tylko uruchomienie pomia-ru czasu: $benchmark->start();. Od te-go momentu będzie mierzony czas, ja-ki upłynął między kolejnymi markerami aż do momentu zakończenia pomiarów wywołaniem $benchmark->stop();.

Tuż przed i po wywołaniu doSth() ustawiamy nasze markery wywołując: $benchmark->setMarker( 'Marker #1'

);. Argumentem metody setMarker() jest nazwa markera – może ona być dowol-na, ale dobrze jest nadawać nazwy uła-twiające późniejszą identyfikację mar-

kerów w wynikach. Warto również za-znaczyć, że wywołanie metod start() i stop() również powoduje powstanie markerów, których nazwy to odpowied-nio Start i Stop.

Metoda getProfiling() zwraca tabli-ce z wynikami. Tablica ta (dla naszego przykładu) wygląda jak na Listingu 2. Ta-blica ta jest ponumerowana od 0 do n-1, gdzie n to liczba markerów (pamiętajmy, że wywołanie start() i stop() również liczy się jako marker). Każdy element tej tablicy to kolejna tablica zawierająca cztery elementy: name – nazwa marke-ra, time – uniksowy znacznik czasu za-pisany w momencie wywołania marke-ra, diff – czas w sekundach, jaki upły-nął miedzy obecnym a poprzednim mar-kerem (w przypadku Start jest to znak „-”, ponieważ nie było wcześniejszego po-miaru) oraz total – całkowity czas, jaki upłynął od wywołania pierwszego mar-kera do bieżącego.

No dobrze, ale po co nam tyle mar-kerów do pomiaru czasu wykonania jed-nej funkcji? Markery stosujemy, aby ozna-czyć miejsca w kodzie, dla których mie-rzymy czas wykonania i dla jednej funkcji wystarczyłoby wywołać metody start() i stop(). My jednak chcemy zidentyfiko-wać najwolniej działające partie kodu w większym skrypcie.

Pomiar czasu rejestracji użytkownikaZawartość Listingu 3 jest już bardziej po-dobna w działaniu do typowej aplikacji in-ternetowej. Mamy tam operacje na ba-zie danych i na ciągach. Przedstawiony skrypt odpowiada za rejestrację nowego użytkownika w naszym serwisie interne-towym. Darujemy sobie tworzenie formu-larza i przykładowe dane, które normal-nie wprowadziłby użytkownik, zapiszemy do zmiennych. Wcześniej jednak musi-my dołączyć do skryptu niezbędne klasy i funkcje: Benchmark/Timer.php posłuży do pomiaru wydajności, filter.php (Listing 4) zawiera funkcje filtrujące numer telefo-nu i komentarze, a w generators.php (Li-sting 5) deklarujemy funkcję generującą losowe hasło.

Po załadowaniu odpowiednich plików tworzymy nową instancję klasy Bench-mark _ Timer i uruchamiamy pomiar cza-su. Ustawiamy zmienne symulujące da-ne użytkownika. Następnie filtrujemy nu-mer telefonu tak, żeby zawierał same cy-fry wywołując funkcję telephone($phone) oraz oraz oczyszczamy komentarz ze znaczników HTML mogących po-służyć do ataku XSS: $comment =

comments($comment). Następnie generuje-my losowe hasło ($pass = passGen()), łą-czymy się z bazą danych i umieszczamy

Rysunek 1. Wynik działania klasy Benchmark_Profiler

Rysunek 2. Wynik profilowania skryptu z Listingu 17

www.phpsolmag.org4


PHP Solutions Nr 6/2006

w niej przykładowe dane (tabela bazo-danowa, na której wykonujemy te opera-cje, została przedstawiona na Listingu 6). Na koniec skryptu wyświetlamy zmienne $phone i $comment zawierające przefiltro-wane dane wejściowe w celu sprawdze-nia, czy są poprawne. Oczywiście nie za-pominamy o podaniu wyników pomiarów poprzez wywołanie var _ dump( $bench-

mark->getProfiling()). Pomiędzy wspo-mnianymi operacjami wstawiamy punkty pomiaru czasu i sprawdzamy wyniki. Li-sting 7 przedstawia rezultaty, jakie uzy-skałem na mojej maszynie testowej. Naj-pierw widzimy efekt filtrowania zmiennych zawierających telefon i komentarz, a na-stępnie czasy wykonania poszczególnych części kodu.

Benchmark_ProfilerWyniki z Listingu 7 są trudne w analizie: zwłaszcza, jeżeli ustawimy wiele pułapek mierzących czas. Mamy jednak do dyspo-zycji klasę Benchmark _ Profiler, która po-wie nam, jaki jest procentowy udział po-szczególnych sekcji skryptu w czasie jego wykonania. Na Listingu 8 przedstawiamy zmodyfikowany kod z Listingu 3.

Przyjrzyjmy się bliżej zmianom w tym kodzie. Przede wszystkim ładujemy teraz

Listing 2. Efekt wykonania skryptu z listingu 1

array(4) { [0]=> array(4) { ["name"]=> string(5) "Start" ["time"]=> string(19) "1153494385.64062800" ["diff"]=> string(1) "-" ["total"]=> string(1) "-" }

[1]=> array(4) { ["name"]=> string(9) "Marker #1" ["time"]=> string(19) "1153494385.64066500" ["diff"]=> string(8) "0.000037" ["total"]=> string(8) "0.000037" }

[2]=> array(4) { ["name"]=> string(9) "Marker #2" ["time"]=> string(19) "1153494385.64189600" ["diff"]=> string(8) "0.001231" ["total"]=> string(8) "0.001268" }

[3]=> array(4) { ["name"]=> string(4) "Stop" ["time"]=> string(19) "1153494385.64191900" ["diff"]=> string(8) "0.000023" ["total"]=> string(8) "0.001291" }

}

Listing 3. Typowe operacje w aplikacjach internetowych

require 'Benchmark/Timer.php';require './filter.php';require './generators.php';$benchmark = new Benchmark_Timer();$benchmark->start();

// przykładowe dane z formularza

$phone = '(33) 455-44-55';

$comment = 'Some comments <script> ... </script>, Some comments <script> ... </script>

<a href="www.somedangerouslink.com"> Safe text <a href="javascript:alert("XSS")">

ClickMe!</a> - <body onload=alert("vulnerable")> Safe text <iframe src=http://

www.notsafe.com/script.html>';

$benchmark->setMarker( 'Variables set' );

// filtrujemy telefon

$phone = telephone( $phone );

$benchmark->setMarker( 'Phone filtred' );

//filtrujemy komentarze

$comment = comments( $comment );

$benchmark->setMarker( 'Comments filtred' );

// generujemy losowe hasło

$pass = passGen();

$benchmark->setMarker( 'Password generated' );

// wykonujemy operacje na bazie danych

$conn = mysql_connect( 'localhost', 'root', '' );mysql_select_db( 'phpsolmag', $conn );$benchmark->setMarker( 'Connection established' );

$sql = 'INSERT INTO users(`pass`, `addDate`, `phone`, `comment`)

VALUES( "'. $pass .'", "'. date("Y-m-d H:i:s") .'", "'. $phone .'", "'. $comment .'" )';

mysql_query( $sql );$benchmark->setMarker( 'Inertion done' );

$benchmark->stop();

// wynik filtrowania

echo 'Phone: '. $phone . '<br />';echo 'Comments: '. $comment;

// wynik pomiarów

echo '<pre>';var_dump( $benchmark->getProfiling() );

echo '</pre>';

Listing 1. Prosty przykład wykorzystania klasy Benchmark_Timer

<?php

require 'Benchmark/Timer.php';$benchmark = new Benchmark_Timer();function doSth(){ $tmp = range(0, 999 );

krsort( $tmp );

return $tmp;}

// rozpoczynamy pomiar

$benchmark->start();

// ustawiamy marker #1

$benchmark->setMarker(

'Marker #1');

// wywołujemy f-cję doSth()

$result = doSth();

// ustawiamy marker #2

$benchmark->setMarker(

'Marker #2');

// kończymy pomiar

$benchmark->stop();

// wyświetlamy informacje uzyskane

// podczas testu

echo '<pre>';var_dump($benchmark->

getProfiling());

echo '</pre>';

?>

www.phpsolmag.org 5



plik z klasą Benchmark _ Profiler i tworzy-my instancję tej klasy. Podobnie jak po-przednio, pomiary rozpoczynamy i koń-czymy metodami start() i stop(). Tutaj podobieństwa z poprzednim przykładem się kończą, bowiem w przypadku Bench-mark _ Profiler zamiast markerów używa-my sekcji. Oprócz tego, że mierzony jest globalny czas wykonania między wywo-łaniami start() i stop(), osobne pomia-ry dokonywane są dla sekcji oznaczo-nych metodami enterSection() i leave-Section() oznaczającymi początek i ko-niec sekcji.

Argumentem każdej z tych metod jest nazwa sekcji, którą ustalamy według na-szych upodobań. W przypadku pomia-ru czasu wykonania funkcji bądź metod można zastosować sztuczkę, która wyłą-cza z pomiarów czas potrzebny na samo wywołanie funkcji i ponowne zwrócenie sterowania do miejsca wywołania funk-cji lub metody. W tym celu możemy we-wnątrz funkcji zadeklarować, że zmien-na zawierająca obiekt klasy Benchmark _

Profiler jest globalna i utworzyć sekcje wewnątrz tej funkcji (Listing 9). Wynik działania testu uzyskamy wywołując me-todę display() pod koniec skryptu, a re-zultat przedstawiamy na Rysunku 1.

Patrząc na Rysunek 1 od razu za-uważymy kolumnę oznaczoną znakiem „%”, która ilustruje procentowy udział każdej operacji w czasie wykonania skryptu między start() a stop(). Ostat-ni wiersz oznaczony jako Global ozna-cza cały skrypt (a w zasadzie cześć po-między początkiem a końcem pomia-rów), więc zajmie on 100% czasu wyko-nania. Kolumna #calls pokazuje, ile razy dana sekcja była wywołana, calls zawie-ra nazwy sekcji, jakie zostały wywołane wewnątrz sekcji odpowiedniej dla każde-go wiersza wyników.

Analizując wyniki widzimy, że najwię-cej czasu zajmuje połączenie się z ba-zą danych i wstawienie nowego rekordu w tabeli bazodanowej. Niestety, operacje wejścia/wyjścia są najbardziej kosztowne, stąd dobrą metodą na zwiększenie szyb-kości działania aplikacji jest keszowanie (ang. caching). W naszym przypadku nie możemy użyć tej ostatniej techniki, gdyż przyspiesza ona odczyt, a my dodajemy dane do bazy. Jeśli bardzo zależy nam na wydajności, to możemy się zająć funkcja-mi filtrującymi nr telefonu i komentarz, co powinno dać nam kilka procent zysku na czasie wykonania. Przyjrzyjmy się więc bliżej funkcjom telephone() i comments().

Benchmark_IterateCzas wykonania skryptu i jego poszcze-gólnych części zależy od wydajności ma-szyny, na której odbywa się test oraz jej obciążenia. Łatwo zauważyć, że cza-sy te różnią się za każdym wywołaniem, ale najczęściej oscylują wokół jakiejś war-tości, z rzadka odbiegając znacząco do normy. Aby pozbyć się tych niedogod-ności, powinniśmy wykonać test w pętli i uśrednić uzyskane czasy. Klasa Bench-mark _ Iterate pozwala na wykonywanie funkcji lub metody w pętli o zadanej licz-bie iteracji. Na Listingu 10 pokazujemy przykład wykorzystania tej klasy wobec funkcji filtrującej komentarze.

Jak widać, nie jest to skomplikowane: po stworzeniu instancji klasy Benchmark _

Iterate uzyskujemy dostęp do jej metod służących testom i wyświetlaniu wyników. Kluczowa jest następująca linia:

$benchmark->run( 1000, 'comments',

$comment );

Nakazuje ona uruchomić funkcję o nazwie podanej jako drugi argument i z parame-

trem przesłanym jako trzeci argument. Liczbę iteracji (wywołań) określa pierw-szy argument. My testujemy funkcję com-ments() z argumentem $comment 1000 razy. Wywołanie get() zwraca nam ta-blicę, która zawiera czas wykonania ko-du w każdej iteracji (klucze są ponume-rowane wg kolejnych liczb naturalnych) oraz czas średni (klucz mean) i liczbę itera-cji (klucz iterations). Ważną rzeczą pod-czas przygotowywania testu jest dobór liczby iteracji. Abyśmy mogli mówić o wia-rygodnych testach, musimy przeprowa-dzić co najmniej 1000 cykli. Kod z Listingu 10 wyświetla tylko czas średni, bo on jest dla nas najistotniejszy:

Mean time: 0.000047s for 1000

iterations of telephone()

Mean time: 0.000141s for 1000

iterations of comments()

Teraz mamy bardziej wiarygodne wyniki i możemy przystąpić do optymalizacji ko-du funkcji comments() (Listing 11). Choć techniki optymalizacyjne nie są przed-miotem tego artykułu, to musimy tu wspo-mnieć o kilku sposród nich, aby wiedzieć, jak uzyskać wzrost wydajności. Nasza funkcja widoczna na Listingu 4 wykorzy-stuje do swego działania wyrażenia regu-larne za pomocą funkcji ereg _ replace(). Pewnie większość z Was wie, iż ereg _

replace() jest zdecydowanie wolniejsza niż pereg _ replace() – możemy więc wykorzystać tę szybszą. Ponieważ jed-nak mamy tylko pozbyć się tagów, więc nie potrzebujemy w ogóle używać wy-rażeń regularnych: wystarczy wbudowa-na do PHP funkcja strip _ tags(), któ-ra powinna być znacznie szybsza niż te pierwsze. W skrypcie z Listingu 10 doda-jemy plik z poprawioną funkcją filtrują (fil-ter2.php).Na Listingu 12 przedstawiamy zmodyfikowany test wydajności i porów-

Listing 4. Funkcje filtrujące

<?php

function telephone( $telephone ){ $telephone = ereg_replace( " ", "", $telephone ); $telephone = ereg_replace( "-", "", $telephone ); $telephone = ereg_replace( "$", "", $telephone ); $telephone = ereg_replace( "$", "", $telephone ); return $telephone;}

function comments( $comment ){ $comment = ereg_replace( "<[^>]*>", "", $comment ); return $comment;}

?>

Listing 5. Funkcja generująca losowe hasło

<?php

function passGen($passLength=10, $startChr=33,$endChr=126){

$password = '';

while ( $passLength-- ){ $password.=chr(mt_rand( $startChr,$endChr));

}

return $password;}

?>

www.phpsolmag.org6



nanie funkcji comments() przed i po opty-malizacji.

Porównując wyniki uzyskałem o po-nad 60% krótszy czas wykonania funk-cji comments(). Jest to dowód na to, że lepiej jest używać funkcji wbudowanych w PHP, niż samemu tworzyć rozwiąza-nia o podobnej funkcjonalności. Wniosek ten nie jest nowy i często można spotkać podobne w podręcznikach PHP. Jednak PHP zawiera ponad 2000 funkcji wbudo-wanych (napisanych w C) i czasem moż-na pominąć tę, której potrzebujemy. Pro-filowanie i testy wydajności zmuszają nas do poszukiwania bardziej optymalnych rozwiązań tam, gdzie przyniesie to naj-większy przyrost wydajności.

Poprawianie dokładności wynikówProfilowanie przy pomocy programów działających w przestrzeni użytkowni-ka (w naszym przypadku napisanych w PHP) ma zasadniczą wadę, którą jest przekłamanie wynikające z narzutu cza-sowego na wykonanie testu. Postaramy się oszacować ten narzut, aby potem odjąć go od wyniku profilowania. W tym celu napiszemy własną klasę dziedzi-czącą po Benchmark _ Iterate. Na Li-stingu 13 przedstawiamy nową klasę My-Iterate. Nadpisujemy w niej tylko dwie metody oryginalnej klasy: run() i get(). W run() najpierw wywołujemy metodę klasy macierzystej:

parent::run( $iterationsCount,

$functionName, $arguments);

z wcześniej przygotowanymi argumenta-mi, a następnie w pętli obliczamy narzut czasowy, jaki powoduje wykonanie po-miarów:

$benchmark->setMarker( '_start_'.$i );

$benchmark->setMarker( '_stop_'.$i );

Listing 6. Tabela 'users' z bazy 'phpsolmag'

-- Baza danych: 'phpsolmag'

-- Struktura tabeli dla 'users'

CREATE TABLE 'users' ( 'ID' int(11) NOT NULL, 'pass' varchar(16) NOT NULL, 'addDate' datetime NOT NULL, 'phone' int(11) NOT NULL, 'comment' text NOT NULL, PRIMARY KEY ('ID')) TYPE=MyISAM AUTO_INCREMENT=115;

Listing 7. Wynik wykonania skryptu z Listingu 3

Phone: 334554455

Comments: Some comments ... , Some comments ... Safe text ClickMe! - Safe text

array(8) {

[0]=> array(4) {

["name"]=> string(5) "Start"

["time"]=> string(19) "1153815327.15625200"

["diff"]=> string(1) "-"

["total"]=> string(1) "-"

}

[1]=> array(4) {

["name"]=> string(13) "Variables set"

["time"]=> string(19) "1153815327.15628900"

["diff"]=> string(8) "0.000037"

["total"]=> string(8) "0.000037"

}

[2]=> array(4) {

["name"]=> string(13) "Phone filtred"

["time"]=> string(19) "1153815327.15635200"

["diff"]=> string(8) "0.000063"

["total"]=> string(8) "0.000100"

}

[3]=> array(4) {

["name"]=> string(16) "Comments filtred"

["time"]=> string(19) "1153815327.15654000"

["diff"]=> string(8) "0.000188"

["total"]=> string(8) "0.000288"

}

Listing 8. Użycie Benchmark_Profiler na przykładzie kodu z Listingu 3

<?php

require 'Benchmark/Profiler.php';require './filter_profiler.php';require './generators.php';$profiler = new Benchmark_Profiler();$profiler->start();

$phone = '(33) 455-44-55';

$comment = 'Some comments <script> ... </script>,

Some comments <script> ... </script>

<a href="www.somedangerouslink.com"> Safe text

<a href="javascript:alert("XSS")">ClickMe!</a> - <body

onload=alert("vulnerable")> Safe text

<iframe src=http://www.notsafe.com/script.html>';


$comment = comments( $comment );

// tworzymy sekcje

$profiler->enterSection('passGen');

$pass = passGen();

$profiler->leaveSection('passGen');

// tworzymy sekcje

$profiler->enterSection('DB connection');

$conn = mysql_connect( 'localhost', 'root', '' );mysql_select_db( 'phpsolmag', $conn );$profiler->leaveSection('DB connection');


VALUES( "'. $pass .'", "'. date("Y-m-d H:i:s") .'", "'. $phone .'", "'. $comment .'" )';

$profiler->enterSection('DB insertion');

mysql_query( $sql );$profiler->leaveSection('DB insertion');

$profiler->stop();

// wyświetlamy wynik

$profiler->display();

?>

www.phpsolmag.org 7



Wynik zapamiętujemy w zmiennej skła-dowej $overhead. Metody setMarker() wyglądają znajomo, ponieważ ich działa-nie jest identyczne, jak w przypadku kla-sy Benchmark _ Timer. Jest to w zasadzie ta sama metoda, gdyż klasa Benchmark _

Iterate dziedziczy z klasy Benchmark _

Timer. Przejdźmy do metody get(): uży-wamy jej aby uzyskać wyniki testów, więc najpierw wywołujemy tę samą metodę dla klasy Benchmark _ Iterate:

$result = parent::get();

a później od uzyskanego wyniku odejmu-jemy wcześniej oszacowany narzut:

$result['mean'] -= $this->overhead;

Na Listingu 14 pokazujemy wykorzysta-nie tej klasy na przykładzie naszej funkcji do filtrowania komentarzy.

Przy powtórzonych testach okaza-ło się, że zoptymalizowana funkcja com-ments() działa nawet 75% szybciej (bez eliminacji narzutu czasowego pomiarów było to ponad 60%). Widać więc, że sa-me testy mogą częściowo zafałszować rezultaty, więc dobrze jest to uwzględnić w wyniku końcowym.

WynikSprawdźmy teraz, jak bardzo wzrosła wy-dajność całej aplikacji po dokonanych zmianach. Na Listingu 15 pokazujemy wykorzystanie klasy Benchmark _ Profil-

er w celu zmierzenia wydajności aplika-cji ze zmodyfikowanym kodem. Porównu-jąc uzyskane rezultaty z wcześniejszymi wynikami widać, że udział czasu przefil-trowania komentarzy spadł poniżej jedne-

go procenta. Tym samym wydajność całej aplikacji wzrosła o kilka procent. To zbyt mało, żeby poczuć satysfakcję, ale pa-miętajmy, że nasz przykład jest specjal-nie uproszczony w celach dydaktycznych. Rzeczywista aplikacja ma więcej kodu, co daje nam więcej szans na znalezienie większego zysku czasu wykonania.

Zalety i wady pakietu BenchmarkInstalacja pakietu Benchmark jest bardzo łatwa; często stanowi on element stan-dardowej instalacji PHP, co pozwala nam szybko i bezproblemowo wykorzystać je-go potencjał.

Podstawową wadą klas Benchmark jest wspomniany wcześniej dodatkowy narzut czasowy podczas testów, który może zafałszować wyniki. Istnieje jednak

Listing 9. Przykład wyłączenia czasu samego wywołania funkcji na przykładzie z Listingu 4

<?php

function telephone($telephone){ global $profiler; $profiler->enterSection(

'telephone');

$telephone=preg_replace(

"(\D)", "", $telephone );

$profiler->leaveSection(

'telephone');

return $telephone;}

function comments($comment){ global $profiler; $profiler->enterSection(

'comments');

$comment = strip_tags(

$comment );

$profiler->leaveSection(

'comments');

return $comment;

}

?>

Rysunek 3. Wynik po zmianie flagi na „–u”

Parametry skryptu pprofpSkładnia pprofp jest następująca:

pprofp <opcje> <plik>

Oto opcje sortowania:

-a: sortowanie wg nazw procedur,-l: sortowanie wg liczby wywołań procedur,-r: sortowanie wg rzeczywistego czasu spędzonego w procedurach.-R: sortowanie wg rzeczywistego czasu spędzonego w procedurach z uwzględnieniem

wywołań procedur potomnych,-s: sortowanie wg czasu systemowego spędzonego w procedurze,-S: sortowanie wg czasu systemowego spędzonego w procedurach z uwzględnieniem

wywołań procedur potomnych,-u: sortowanie wg czasu użytkownika spędzonego w procedurach,-U: sortowanie wg czasu użytkownika spędzonego w procedurach z uwzględnieniem

wywołań procedur potomnych,-v: sortowanie wg średniego czasu spędzonego w procedurach,-z: Sortowanie (domyślne) wg czasu systemowego i użytkownika spędzonego w pro-

cedurach.

Opcje wyświetlania:

-c: wyświetlenie czasu rzeczywistego w całym drzewie wywołań.-i: wyłączenie z raportu funkcji wbudowanych w PHP,-O <cnt>: określa maksymalna liczbę wyświetlanych procedur (domyślnie 15),-t: wyświetla skompresowane drzewo wywołań,-T: wyświetla nieskompresowane drzewo wywołań.

www.phpsolmag.org8



jeszcze inna wada korzystania z progra-mów profilujących, które działają w prze-strzeni użytkownika. Zapewne zauwa-żyliście, ile dodatkowych linii kodu musi-my dopisać w różnych miejscach aplika-cji, aby dało się ją przetestować. Wiel-kość dodatkowego kodu jest różna w za-leżności od tego, co chcemy konkretnie zbadać (pojedynczą funkcję, całość czy część aplikacji) i od wybranego pakietu testującego (istnieją inne, niż te zawarte w PEAR). Te wady są (przynajmniej czę-ściowo) eliminowane przez programy pro-filujące, które wykorzystują rozszerze-nia ZEND.

APD (Advanced PHP Debugger)APD jest pakietem PECL (http://pecl.php.net), czyli rozszerzeniem PHP. Śledzi on uruchomienia i zakończenia zarówno funkcji użytkownika, jak i tych wbudowanych w PHP. Ponadto APD za-pisuje informacje o wywołaniach in-

clude i require. Instalacja pakietu za-leży od systemu operacyjnego i wersji

PHP i opisujemy ją w ramkach Instala-cja pod Windows oraz Instalacja pod Li-nuksem. Po pomyślnej instalacji powinni-śmy zobaczyć informacje o APD wywołu-jąc phpinfo().

Instalacja APD pod LinuksemAby skorzystać z APD pod Linuksem, mu-simy mieć zainstalowany pakiet php-de-vel, który zawiera podstawowe narzędzia do tworzenia rozszerzeń PHP. W więk-szości dystrybucji Linuksa zainstalujemy go używając apt-get:

apt-get php-devel

potem możemy zainstalować samo APD:

pear install APD

Teraz w pliku php.ini w sekcji [Zend] dopi-szemy ustawienia:

[Zend]

...

zend_extension = /lokalizacja/apd.so

apd.dumpdir = /katalog/z/plikiem/sledzenia

apd.statement_trace = 0

Zmienna zend _ extension wskazuje lo-kalizację APD, zaś apd.dumpdir określa miejsce na dysku, w którym będą zapisy-wane wyniki profilowania.

Instalacja APD pod WindowsInstalacja APD pod Windowsd zależy głownie od wersji PHP, z którą APD ma współpracować. Najprostsza jest instala-cja dla PHP5, którą tu opiszemy.

Pierwszym, co musimy zrobić, jest po-branie ze strony http://pecl4win.php.net/ext.php/php_apd.dll binarnej wersji biblio-teki (musimy wybrać odpowiedni plik wer-sji PHP) oraz jej skopiowanie do katalo-gu, w którym PHP szuka rozszerzeń. Fol-der ten jest określony przez zmienną ex-tension _ dir w pliku php.ini. Następnie w sekcji, w której dodajemy rozszerze-nia, musimy dopisać: extension=php _

apd.dll, a w sekcji [Zend]:

zend_extension_debug_ts =

"x:\lokalizacja\apd\php_apd.dll"

apd.dumpdir = x:\tmp

apd.statement_trace = 0

Zmienna zend _ extension _ debug _ ts określa lokalizację APD, a apd.dump-dir – katalog, w którym będą zapisywane wyniki profilowania. Musimy jeszcze zdo-być plik pprofp, który jest skryptem PHP i służy do analizowania tych wyników. Plik ten znajduje się w pakiecie źródło-wym, który można pobrać ze strony http://pecl.php.net/package/apd.

Instalacja APD dla PHP4 jest nieco bardziej skomplikowana, a jej opis w języ-ku angielskim można znaleźć pod adre-sem: http://wiki.splitbrain.org/php:apd.

APD w akcjiPo pomyślnej instalacji APD chcemy wy-próbować jego działanie. Zmodyfikujemy

Listing 10. Wykorzystanie klasy Benchmark_Iterate wobec funkcji filtrującej komentarze

<?php

require 'Benchmark/Iterate.php';require './filter.php';$benchmark = new Benchmark_Iterate();$comment = 'Some comments <script> ... </script>, Some comments <script> ...

</script>

<a href="www.somedangerouslink.com"> Safe text <a

href="javascript:alert("XSS")">ClickMe!</a> - <body

onload=alert("vulnerable")> Safe text <iframe src=http://www.notsafe.com/

script.html>';

// uruchamiamy test

$benchmark->run( 1000, 'comments', $comment );

$commentResult = $benchmark->get();

// wyswietlenie wyniku

echo '<p>Mean time: ' .$commentResult['mean'] . 's for ' .$commentRes

ult['iterations'].

' iterations of comments()</p>';

?>

Rysunek 4. Czas wykorzystania procesora przez poszczególne funkcje

www.phpsolmag.org 9



więc prosty przykład z Listingu 1. Zmiany, które prezentujemy na Listingu 16 polega-ły na usunięciu wszelkich operacji związa-nych z klasą Benchmark _ Timer i dodaniu nowej funkcji apd _ set _ pprof _ trace() na początku skryptu, które rozpoczyna śledzenie działania skryptu. APD posia-da tez kilka innych funkcji, ale my wyko-rzystamy jedynie tę wymienioną. Jak wi-dać, aby wykonać profilowanie, wymaga-na jest tylko minimalna modyfikacja kodu aplikacji: wystarczy, że wywołanie na po-czątku głównego pliku naszej aplikacji do-damy apd _ set _ pprof _ trace(). Po wy-konaniu skryptu z Llistingu 17 wynik profi-lowania zostaje zapisany w pliku o nazwie pprof.xxxxx.yy, gdzie xxxxx to PID proce-su serwera, który uruchomił profilowany skrypt, a yy to kolejny numer porządkowy. Katalog, w którym ten plik zostanie zapi-sany, jest określony przez opcjonalny pa-rametr funkcji apd _ set _ pprof _ trace(). Jeżeli ten ostatni nie został zdefiniowany, to położenie tego folderu określa zmienna apd.dumpdir z pliku php.ini. Struktura pli-ku pprof jest opisana w dokumentacji, ale odradzamy własnoręczne analizowanie jego zawartości, ponieważ istnieje do te-go proste i efektywne narzędzie – skrypt PHP o nazwie pprofp. Wywołujemy go z linii poleceń w katalogu, w którym się on znajduje, podając ścieżkę dostępu do pli-ku z wynikami:

php pprofp –z /tmp/profiling/pprof.02596.8

Spowoduje to przeanalizowanie poda-nego jako parametr pliku, utworzone-go wcześniej przez funkcję apd _ set _

pprof _ trace(). Program pprofp ma sze-reg flag i opcji opisanych w Ramce Pa-rametry skryptu pprofp. Nam najbardziej przydadzą się flagi –z i –r. Wynikiem in-terpretacji naszego pliku jest tabela poka-zana na Rysunku 2.

Na Rysunku 2 pokazujemy kilka istot-nych informacji. Na górze widać podsta-wowe dane, takie jak lokalizacja testowa-

nego pliku i czas wykonania całego skryp-tu. Dalej znajduje się tabela podająca bar-dziej szczegółowe informacje, jak procen-towy udział danej funkcji w czasie wykona-nia całego skryptu, rzeczywisty czas, ja-ki minął (kolumna Real), czas spędzony na wykonywaniu kodu użytkownika przez procesor (kolumna User) oraz czas spę-dzony na wywołaniach systemowych (ko-lumna System). W kolumnie Calls zapisa-na jest informacja o liczbie wywołań danej funkcji (nazwa funkcji to ostatnia kolumna).

Ostatni wiersz naszej tabeli opisuje funk-cję main(), a przecież na naszym listingu nie było funkcji o takiej nazwie! Skąd więc się ona wzięła? Otóż main oznacza tu cały skrypt od momentu rozpoczęcia śledzenia.

Przykład z życia wziętyNasz przykład jest dość prosty, więc cza-sy wykonania są minimalne. Weźmy więc większą aplikację: nie będziemy jej two-rzyć od zera, tylko skorzystamy z gotowe-go systemu portalowego, którym jest PHP-

Listing 11. Zoptymalizowana funkcja comments()

<?php

function comments2( $comment ){ $comment = strip_tags( $comment

);

return $comment;}

?>

Listing 12. Porównanie wydajności funkcji przed i po optymalizacji.

<?php

require 'Benchmark/Iterate.php';require './filter.php';require './filter2.php';$benchmark = new Benchmark_Iterate();$comment = 'Some comments <script> ... </script>, Some comments <script> ...

</script>




script.html>';



$benchmark->run( 1000, 'comments2', $comment );

$comment2Result = $benchmark->get();

echo '<p>Mean time: '.$commentResult['mean'] . 's for '.$commentResult['iterati

ons'].


$percent = round( (1-($comment2Result['mean']/$commentResult['mean']))*100, 1 );

echo '<p>Mean time: '.$comment2Result['mean'].'s ('. $percent .'% faster) for '.

$comment2Result['iterations'].' iterations of comments2()</p>';

?>

Listing 13. Klasa MyIterate

<?php

require_once 'Benchmark/Iterate.php';

class MyIterate extends Benchmark_Iterate{ private $overhead;

public function run(){ $arguments = func_get_args();

$iterationsCount = array_shift( $arguments );

$functionName = array_shift( $arguments );

$arguments = array_shift( $arguments );

parent::run( $iterationsCount, $functionName, $arguments );

$benchmark = new Benchmark_Iterate(); for ( $i=0; $i<$iterationsCount; $i++ ){ $benchmark->setMarker( '_start_'.$i );

$benchmark->setMarker( '_stop_'.$i );

}

$result = $benchmark->get();

$this->overhead = $result['mean'];

}

public function get(){ $result = parent::get();

$result['mean'] -= $this->overhead;

return $result;

}

}

?>

www.phpsolmag.org10



NUKE. W Internecie łatwo można znaleźć opis jego instalacji, załóżmy więc, że ma-my już wszystko zainstalowane i skonfi-gurowane. Nie będziemy dokonywać żad-nych zmian w aplikacji, dodamy tylko na początku pliku index.php linijkę:

apd_set_pprof_trace();

Następnie wywołamy w przeglądarce tak zmodyfikowany plik i przeanalizujemy uzyskane wyniki poleceniem:

php pprofp –r /lokalizaja/pliku/pprof

Na mojej maszynie testowej najwięcej czasu zajęło wykonanie funkcji mysql _

query() oraz file(), co jest normalne, po-nieważ wejście/wyjście jest wąskim gar-dłem każdej aplikacji. Możnaby znacznie przyspieszyć te operacje keszując wyni-ki zapytań wysyłanych do bazy danych: wiele interfejsów bazodanowych posiada taką funkcjonalność, pozwalającą na ko-rzystanie z wcześniejszych zapytań.

Sprawdźmy teraz, które procedury trwały najdłużej (bez uwzględniania pod-procedur):

php pprofp –u /lokalizaja/pliku/pprof

Wynik powinien być podobny do przed-stawionego na Rysunku 3.

Spójrzmy na pierwsze cztery funkcje, których wywołanie zdominowało czas wykonania całego skryptu. Znowu znaj-dujemy tu operacje dostępu do bazy da-nych. Funkcja addslahes(), wywoływana zapewne ze względów bezpieczeństwa, jest konieczna. Spójrzmy teraz na trzecią na liście funkcję readdir() – została ona wywołana 633 razy, co wielokrotnie prze-kracza liczbę katalogów z plikami aplika-cji. Gdyby to była nasza aplikacja, to mo-glibyśmy każdorazowo zapamiętac wynik odczytania zawartości katalogu w zmien-nej, zamiast wielokrotnie wywoływać re-addir() dla tych samych katalogów. Ko-lejną funkcją na naszej liście jest eregi _replace() i jak już wspomnieliśmy, można ją zastąpić szybszym odpowiednikiem – preg _ replace().

Pomińmy teraz czas potrzeby na wykonanie operacji wejścia/wyjścia i sprawdźmy, ile poszczególne funkcje za-brały czasu samego procesora:

php pprofp –z /lokalizaja/pliku/pprof

Wyniki przedstawiamy na Rysunku 4. Teraz pierwsze miejsce zajmuje ini _

set(). Żeby sprawdzić, czy rzeczywiście jest potrzebna i gdzie występują wywo-

Listing 14. Wykorzystanie klasy MyIterate

<?php

require 'MyIterate.php';require './filter.php';require './filter2.php';$benchmark = new MyIterate();$comment = 'Some comments <script> ... </script>, Some comments <script> ... </script>




script.html>';



$benchmark->run( 1000, 'comments2', $comment );

$comment2Result = $benchmark->get();

echo '<p>Mean time: ' .

$commentResult['mean'] . 's for ' .

$commentResult['iterations'] .


$percent = round( (1-($comment2Result['mean']/$commentResult['mean']))*100, 1 );

echo '<p>Mean time: ' .

$comment2Result['mean'] . 's ('. $percent .'% faster) for ' .

$comment2Result['iterations'] .


?>

Listing 15. Sprawdzamy jak bardzo wzrosła wydajność naszej aplikacji.

<?php

require 'Benchmark/Profiler.php';require './generators.php';require './filter_profiler.php';require './filter2_profiler.php';$profiler = new Benchmark_Profiler();$profiler->start();

$phone = '(33) 455-44-55';

$comment = 'Some comments <script> ... </script>, Some comments <script> ... </script>

<a href="www.somedangerouslink.com"> Safe text <a href="javascript:alert("

XSS")">ClickMe!</a> - <body onload=alert("vulnerable")> Safe text <iframe

src=http://www.notsafe.com/script.html>';


$comment = comments2( $comment );

$profiler->enterSection('passGen');

$pass = passGen();

$profiler->leaveSection('passGen');

$profiler->enterSection('DB connection');

$conn = mysql_connect( 'localhost', 'root', '' );

mysql_select_db( 'phpsolmag', $conn );

$profiler->leaveSection('DB connection');


VALUES( "'.$pass .'", "'.date("Y-m-d H:i:s").'", "'.$phone.'", "'.$comment.'" )';

$profiler->enterSection('DB insertion');

mysql_query( $sql );

$profiler->leaveSection('DB insertion');

$profiler->stop();

$profiler->display();

?>

Listing 16. Prosty przykład użycia APD

<?php

apd_set_pprof_trace();

function doSth(){ $tmp = range( 0, 999 );

krsort( $tmp );

return $tmp;}

// wywołanie funkcji doSth()

$result = doSth();

?>

www.phpsolmag.org 11



łania do tej funkcji, możemy się posłużyć opcją –t, która wyświetli nam drzewo wy-wołań funkcji. Przeanalizowaliśmy pozo-stałe funkcje spośród najbardziej czaso-chłonnych oprócz define(), która pojawiła się wysoko dopiero w tej klasyfikacji. Jest ona wywoływana 294 razy i choć każde jej użycie niesie ze sobą minimalny na-rzut czasowy, to jednak podsumowując jej wszystkie wywołania możemy stwier-dzić, że „pożarła” ona aż 11,1% czasu pracy procesora. Jeśli korzystamy z klas, możemy zamiast tej funkcji użyć stałych klasy definiowanych poleceniem const, co jest znacznie szybsze niż stosowa-nie define().

PodsumowanieNic nie zastąpi dobrych praktyk progra-mistycznych oraz doświadczenia same-go programisty. Jednak jesteśmy tylko ludźmi i czasem popełniamy błędy, któ-re potem trzeba naprawić. Czasem trze-ba poprawiać cudze błędy. Niedostatecz-na wydajność aplikacji (jeśli nie jest spo-wodowana słabym sprzętem) zazwyczaj jest winą błędu programisty lub projektan-ta systemu. Wiele z tych błędów można wychwycić wykorzystując profilowanie. Wskaże nam ono te miejsca w kodzie, które najbardziej opłaca się zoptymalizo-wać, ponieważ dadzą stosunkowo duży przyrost wydajności małym kosztem (nie trzeba analizować całej aplikacji). Mam nadzieje, że udało mi się Wam pokazać, w jaki sposób zidentyfikować wolne par-tie kodu. Pamiętajmy, aby testów doko-nywać w odizolowanym środowisku, bez zbędnych procesów i najlepiej z odłączo-ną siecią, aby nic nie zafałszowało wyni-ków testów. n

Autor jest studentem piątego roku Wy-działu Informatyki Politechniki Szczeciń-skiej. Programowaniem w PHP zajmu-je się od 5 lat. Oprócz PHP, programu-je jeszcze w C/C++ i Javie.kontakt z autorem: [email protected]

O autorze

Testy wydajności i profilowanie aplikacji PHP - Kolos Wikikolos.math.uni.lodz.pl/~archive/Inne -...

Documents

Transcript of Testy wydajności i profilowanie aplikacji PHP - Kolos Wikikolos.math.uni.lodz.pl/~archive/Inne -...