SQL Trace i TKPROF: jak naprawdę analizować problematyczne zapytania w Oracle

Kiedy AWR i ASH to za mało

Pracując jako DBA, wielokrotnie spotykałem się z sytuacją, w której AWR wskazywał problematyczne zapytanie, ASH pokazywał na jakie zdarzenia czeka sesja, ale wciąż brakowało mi kluczowej informacji: co dokładnie dzieje się podczas wykonywania tego konkretnego SQL-a. Agregowane statystyki są świetne do identyfikacji obszaru problemu, jednak aby zrozumieć mechanizm spowolnienia, potrzebujemy zejść na poziom pojedynczego wykonania.

SQL Trace to mechanizm wbudowany w jądro Oracle, który rejestruje każdą operację wykonywaną przez sesję. W przeciwieństwie do statystyk gromadzonych w AWR, trace dostarcza informacji o rzeczywistym przebiegu wykonania, włącznie z dokładnymi czasami poszczególnych faz, liczbą wywołań rekurencyjnych oraz szczegółowymi danymi o oczekiwaniach.

Mechanizm SQL Trace od środka

Gdy włączamy SQL Trace dla sesji, Oracle zaczyna zapisywać do pliku tekstowego szczegółowe informacje o każdej operacji SQL. Rejestrowane są momenty rozpoczęcia i zakończenia parsowania, wykonywania oraz pobierania danych. Dodatkowo trace zawiera informacje o liczbie przetworzonych wierszy, odczytach z bufora oraz odczytach fizycznych z dysku.

Kluczowa różnica między SQL Trace a statystykami z V$SQL polega na tym, że trace pokazuje konkretne wykonanie zapytania w określonym kontekście. Widzimy rzeczywiste wartości zmiennych wiązanych, faktyczne czasy oczekiwań oraz prawdziwy plan wykonania użyty przez optymalizator.

Co rejestruje SQL Trace

• Tekst każdego wykonywanego zapytania SQL wraz z jego identyfikatorem
• Czasy CPU i elapsed time dla każdej fazy wykonania
• Liczbę odczytów logicznych (consistent gets) i fizycznych (physical reads)
• Liczbę przetworzonych i zwróconych wierszy
• Plan wykonania użyty podczas rzeczywistego wykonania zapytania
• Wywołania rekurencyjne generowane przez zapytanie

Metody włączania SQL Trace

Najprostszą metodą jest włączenie trace dla własnej sesji za pomocą ALTER SESSION:

ALTER SESSION SET SQL_TRACE = TRUE;

Jednak w praktyce produkcyjnej rzadko mamy możliwość modyfikacji kodu aplikacji. Znacznie częściej musimy włączyć trace dla sesji innego użytkownika. W tym celu używamy pakietu DBMS_MONITOR:

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(session_id => 147, serial_num => 12345, waits => TRUE, binds => TRUE);

Możemy również włączyć trace dla wszystkich sesji konkretnego użytkownika lub modułu aplikacji. Jest to szczególnie przydatne gdy problem występuje sporadycznie i nie wiemy, która sesja go wywoła:

EXEC DBMS_MONITOR.CLIENT_ID_TRACE_ENABLE(client_id => 'APP_USER_001', waits => TRUE, binds => TRUE);

Włączanie SQL Trace w środowisku produkcyjnym zawsze wiąże się z narzutem wydajnościowym rzędu 5-15%. Nigdy nie zostawiaj trace włączonego na dłużej niż to konieczne i zawsze monitoruj przyrost plików w katalogu diagnostycznym.

Event 10046 i jego poziomy

Dla zaawansowanej diagnostyki zamiast standardowego SQL_TRACE używamy zdarzenia diagnostycznego 10046. Pozwala ono kontrolować poziom szczegółowości zbieranych informacji:

Poziomy szczegółowości eventu 10046

• Poziom 1: podstawowy trace, odpowiednik SQL_TRACE = TRUE
• Poziom 4: trace z wartościami zmiennych wiązanych (bind variables)
• Poziom 8: trace z informacjami o wait events
• Poziom 12: pełny trace zawierający zarówno binds jak i waits

W praktyce niemal zawsze używam poziomu 12, ponieważ dostarcza kompletnych informacji diagnostycznych:

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

Dla sesji innego użytkownika możemy użyć DBMS_SYSTEM.SET_EV lub nowszego DBMS_MONITOR z parametrami waits i binds ustawionymi na TRUE.

Lokalizacja i identyfikacja plików trace

Pliki trace są zapisywane w katalogu określonym przez parametr DIAGNOSTIC_DEST, w podkatalogu trace odpowiedniej instancji. Aby szybko znaleźć plik trace dla konkretnej sesji, używam następującego zapytania:

SELECT VALUE FROM V$DIAG_INFO WHERE NAME = 'Default Trace File';

Dla sesji innego użytkownika musimy najpierw poznać jej identyfikator procesu systemowego (SPID) i na tej podstawie zlokalizować odpowiedni plik. Nazwa pliku trace zawiera nazwę instancji, typ procesu oraz PID.

TKPROF: od surowych danych do raportu

Surowy plik trace jest trudny do analizy. Zawiera tysiące linii z zakodowanymi informacjami, znacznikami czasowymi i identyfikatorami kursorów. TKPROF to narzędzie linii poleceń, które przekształca te dane w czytelny raport.

Podstawowe wywołanie TKPROF:

tkprof ora_12345.trc output.txt sys=no sort=exeela

Parametr sys=no pomija zapytania rekurencyjne wykonywane przez użytkownika SYS, które zazwyczaj nie są przedmiotem analizy. Parametr sort pozwala posortować zapytania według wybranego kryterium; exeela oznacza sortowanie według elapsed time fazy Execute.

Kluczowe opcje TKPROF

• explain=user/password: dodaje plan wykonania do raportu
• aggregate=no: pokazuje każde wykonanie osobno zamiast agregować
• record=filename: zapisuje wszystkie SQL-e do osobnego pliku
• print=n: ogranicza raport do n najważniejszych zapytań

Parse, Execute i Fetch: anatomia wykonania SQL

Każde zapytanie SQL przechodzi przez trzy fazy, które TKPROF raportuje oddzielnie:

Parse

Faza parsowania obejmuje analizę składniową zapytania, sprawdzenie uprawnień oraz wygenerowanie planu wykonania. Wysoka liczba operacji parse wskazuje na brak współdzielenia kursorów, co często wynika z używania literałów zamiast zmiennych wiązanych.

Execute

Faza wykonania to właściwa praca związana z realizacją zapytania. Dla zapytań DML (INSERT, UPDATE, DELETE) większość czasu i zasobów zużywana jest właśnie tutaj. Dla SELECT-ów ta faza może być minimalna.

Fetch

Pobieranie danych dotyczy tylko zapytań SELECT. Wysoka wartość w tej fazie wskazuje na przetwarzanie dużej liczby wierszy. Warto zwrócić uwagę na stosunek liczby fetch calls do liczby zwróconych wierszy; wartość bliska 1:1 może oznaczać nieefektywne pobieranie pojedynczych wierszy.

Interpretacja czasów i statystyk

Raport TKPROF zawiera kilka kluczowych metryk, które należy analizować łącznie:

CPU Time pokazuje czas procesora zużyty przez zapytanie. Elapsed Time to całkowity czas wykonania. Różnica między nimi wskazuje na czas spędzony na oczekiwaniu, na przykład na I/O lub blokadach.

Jeśli CPU Time jest zbliżony do Elapsed Time, problem leży w samym zapytaniu: nieefektywny plan, brak indeksów, zbyt duża liczba przetwarzanych wierszy. Jeśli natomiast Elapsed Time znacząco przewyższa CPU Time, musimy szukać przyczyny w wait events.

Consistent Gets pokazuje liczbę odczytów logicznych z bufora. Physical Reads to odczyty z dysku. Wysoki stosunek physical reads do consistent gets może wskazywać na niewystarczający buffer cache lub skanowanie tabel, które nie mieszczą się w pamięci.

Zawsze porównuj liczbę przetworzonych wierszy (rows processed) z liczbą zwróconych wierszy. Jeśli zapytanie przetwarza miliony wierszy aby zwrócić kilka, masz problem z selektywnością warunków lub brakiem odpowiedniego indeksu.

Plan wykonania w kontekście rzeczywistych statystyk

TKPROF pozwala zobaczyć plan wykonania obok rzeczywistych statystyk. To kluczowe, ponieważ plan może wyglądać poprawnie, ale statystyki ujawniają problem. Typowy przykład to nested loops, które dla małych zbiorów działają świetnie, ale gdy liczba iteracji rośnie do tysięcy, stają się wąskim gardłem.

W raporcie TKPROF przy każdej operacji planu widzimy kolumnę Rows, pokazującą rzeczywistą liczbę wierszy przetworzonych przez tę operację. Porównanie z szacunkami optymalizatora (dostępnymi w EXPLAIN PLAN) często ujawnia źródło problemu: nieaktualne statystyki obiektów.

Studium przypadku: diagnoza wolnego raportu

Użytkownik zgłasza, że raport dzienny wykonuje się 45 minut zamiast zwykłych 5. AWR pokazuje zapytanie z wysokim elapsed time, ale nie wiadomo dlaczego.

Włączam trace dla sesji wykonującej raport na poziomie 12. Po zakończeniu raportu generuję raport TKPROF. Analiza ujawnia, że jedno zapytanie wykonuje 2.8 miliona consistent gets przy zaledwie 1200 zwróconych wierszach. Plan pokazuje full table scan na tabeli transakcji.

Sprawdzam warunki WHERE: filtr po dacie używa funkcji TRUNC na kolumnie indeksowanej, co uniemożliwia wykorzystanie indeksu. Przepisanie warunku z TRUNC(data_transakcji) = TRUNC(SYSDATE-1) na data_transakcji >= TRUNC(SYSDATE-1) AND data_transakcji < TRUNC(SYSDATE) przywraca wykorzystanie indeksu i czas wykonania spada do 3 minut.

Typowe błędy przy analizie trace

• Analizowanie trace z włączonym sys=yes, co zaśmieca raport zapytaniami rekurencyjnymi
• Ignorowanie sekcji wait events i skupianie się wyłącznie na planie wykonania
• Porównywanie czasów z różnych wykonań bez uwzględnienia stanu cache
• Włączanie trace dla zbyt wielu sesji jednocześnie, co przeciąża system I/O
• Zapominanie o wyłączeniu trace, co prowadzi do zapełnienia dysku