Przeprowadzałam ostatnio testy wydajnościowe dwóch skryptów. Skrypty miały to samo zadanie do wykonania, jednak używały innych funkcji. Trzeba było zweryfikować, który z nich jest wydajniejszy dla różnych ilości przetwarzanych rekordów.
Oczywiście miałam swoje typy.
Testowałam dla 100, 10000 oraz 1000000 rekordów.
Moje przewidywania sprawdziły się. Ale tylko dla pierwszych dwóch przypadków.
Dla 100 i 10000 rekordów skrypt pierwszy był szybszy. Jednak dla największej ilości danych zaczynały się dziać dziwaczne rzeczy - nagle skrypt do tej pory wolniejszy - znacznie przyspieszał. I to nie tylko w stosunku do pierwszego skryptu ale również w stosunku do samego siebie uruchamianego dla mniejszej ilości rekordów!
Magia czy co?!
Oczywiście nie wierzę w takie magiczne przyspieszania więc zaczęłam sprawdzać kod. Może gdzieś jest błąd? Może są cachowane dane i drugi skrypt ma łatwiej?
Zmieniłam kolejność wykonywania skryptów.
Sprawdziłam, czy ilość danych i warunki wywołania obu skryptów są identyczne.
Zweryfikowałam, czy nigdzie nie są wywoływane blędy.
Przepisałam nieco kod na bardziej optymalny - z bulk collect na bulk collect z klauzulą LIMIT, tak dla pewności.
I testuję i testuję. Ale wyniki dalej uparcie pokazują, że dla mniejszej ilości rekordów skrypt 1 jest szybszy a dla większej ilości - skrypt 2 nagle ogromnie przyspiesza i bije rekordy...
Normalnie zonk. NIEMOŻLIWE!? A jednak wyniki nie kłamią.....
Przykładowe wyniki przetwarzania, w sekundach:
run 1: SKRYPT_1; 100; 0,21
run 1: SKRYPT_2; 100: 0,75
run 2: SKRYPT_1; 10000; 3,54
run 2: SKRYPT_2; 10000: 50,70
run 3: SKRYPT_1; 1000000; 47,11
run:3 SKRYPT_2; 1000000: 20,69
Jakieś pomysły?
Cóż, jak to bywa, intrygujące wyniki nie zwiastują intrygującego rozwiązania a najczęściej banalny jednak błąd.
Przyczyną przyspieszenia skrytpu nie były jakieś magiczne mechanizmy Oracle a najzwyklejszy błąd logowania czasu :) Czas był wyliczony na typie danych TIMESTAMP i wyciągane ze zmiennej sekundy.
Właśnie, sekundy. Przy małej ilości rekordów, gdy czasy wykonania były liczone w sekundach - wszystko było w porządku, skrypt pierwszy wykonywał się szybciej. Przy dużej ilości rekordów skrypt szedł powyżej minuty - a minuty te były ignorowane, wyciągane były tylko sekundy! Skrypt dwa wcale nie szedł szybko. naszym przykładzie czas run 3 skyptu 2 wcale nie wynosił 20 sekund a 100 MINUT i 20 sekund . Tylko minuty nie były zliczane jakos czas wykonania.
-- logowanie tylko sekund
DBMS_OUTPUT.PUT_LINE('o_char(round(extract(second from (systimestamp - dtime)),2), '99990D00'));
-- poprawne logowanie
DBMS_OUTPUT.PUT_LINE(to_char(round(extract( day from(systimestamp - dtime)*24*60*60*100)/100,2), '99990D00'));
Ot, i cała tajemnica.
Głupia pomyłka a dwa dni można sobie w buty wsadzić :D
Komentarze
Prześlij komentarz