Bardzo wolne zapytanie

Robię proste wyszukiwanie rekordu w jednej bazodanowej tabeli, po jednopolowym kluczu głównym. Wszelkie statystyki są policzone, dane mają normalny zdrowy rozkład. To musi działać szybko, nieprawdaż?

Też tak myślałem.

Niewinnie wyglądający kod

Niezbyt skomplikowana aplikacja, działająca na dużej objętościowo ale prostej strukturalnie bazie Oracle, nagle zaczęła sprawiać problemy. Regularnie przycinała się, wstrzymując działanie na dziesiątki sekund, minuty nawet.

Problemy sprawiało stale to samo zapytanie, wyglądające jakoś tak (pythonowy kod korzystający z SQLAlchemy).

query = abc_table.select()\
                 .where(abc_table.c.klucz == parametr)
result = db_session.execute(query)

gdzie problematyczna tabela miała definicję::

CREATE TABLE abc (
       klucz VARCHAR2(32) NOT NULL PRIMARY KEY,
       wartosc INTEGER NOT NULL,
       komentarz VARCHAR2(512));

Zapytanie było naprawdę po kluczu, wg logów było translowane na coś zbliżonego do (pomijam etykiety kolumn i nieistotne formatowanie)

SELECT klucz, wartosc, komentarz
FROM abc
WHERE klucz = :parametr

Dla klucza istniał poprawny niezdegenerowany indeks, wszelkie statystyki były poprawnie policzone. Natychmiast padło oczywiste podejrzenie coś trzyma blokady ale – nie, nie udało się znaleźć jakiegokolwiek dowodu by występowały.

Wszelkie próby wykonywania podobnych zapytań z palca (włącznie z wiernym a nieco rozpaczliwym przeklejeniem znak po znaku logowanego przez aplikację tekstu SQL) kończyły się błyskawicznie a prezentowane dla nich plany zapytania zakładały używanie indeksu.

Administratorowi bazy danych udało się na koniec dopatrzeć (przeglądając historyczne plany zachowane przez bazę w jej cache), że zapytania te bywały wykonywane full-table scan-em.

Dodanie w aplikacji podpowiedzi nakazującej użycie indeksu spowodowało, że … zaczął się objawiać full index scan.

Prosty skrypt wycięty z programu i robiący to jedno pojedyncze zapytanie również działał szybko.

A w tle tykały rozmaite sprawy międzyfirmowej polityki.

Problem ostatecznie udało się rozwiązać, poniżej opisuję o co chodziło, jaki miało to związek z Pythonem i jak sprawę zobaczyć w sqlplus-ie. Jako ćwiczenie intelektualne, proponuję zanotowanie przed przejściem do dalszej lektury pomysłów nawet nie na o co chodziło ale co można by sprawdzać.

Przygotowanie danych do zabawy

Zasymulowanie problemu wymaga w miarę sporej tabeli. Można ją stworzyć np. tak:

CREATE TABLE abcd_test_table(
       klucz VARCHAR2(32) NOT NULL PRIMARY KEY,
       wartosc INTEGER NOT NULL,
       komentarz VARCHAR2(512)
);

CREATE OR REPLACE PROCEDURE abcd_napelnij(
        first_record_no IN INTEGER, last_record_no IN INTEGER)
AS
    v_idx  INTEGER := first_record_no;
BEGIN
    LOOP
       INSERT INTO abcd_test_table(klucz, wartosc, komentarz)
            VALUES ('ABC' || TO_CHAR(v_idx), v_idx, 'Ala ma kota' || TO_CHAR(v_idx));
       EXIT WHEN ( v_idx >= last_record_no );
        v_idx := v_idx + 1;
    END LOOP;
    COMMIT;
END;
/

-- W paru krokach by uniknąć timeoutów TNS i ograniczać rozmiar transakcji.
EXECUTE abcd_napelnij(1000000, 1100000);
EXECUTE abcd_napelnij(1100001, 1200000);
EXECUTE abcd_napelnij(1200001, 1300000);
EXECUTE abcd_napelnij(1300001, 1400000);
EXECUTE abcd_napelnij(1400001, 1500000);
EXECUTE abcd_napelnij(1500001, 1600000);
EXECUTE abcd_napelnij(1600001, 1700000);
EXECUTE abcd_napelnij(1700001, 1800000);
EXECUTE abcd_napelnij(1800001, 1900000);
EXECUTE abcd_napelnij(2000000, 2100000);
-- ... i ewentualnie jeszcze trochę

Najprostsza ilustracja problemu

> SELECT * FROM abcd_test_table WHERE klucz = 'ABC1';

0 rows selected (0.01 seconds)

> SELECT * FROM abcd_test_table WHERE klucz = N'ABC2';

0 rows selected (1.16 seconds)

> SELECT * FROM abcd_test_table WHERE klucz = 'ABC1000001';

1 row selected (0.00 seconds)

> SELECT * FROM abcd_test_table WHERE klucz = N'ABC2000001';

1 row selected (1.10 seconds)

O co chodzi z tym N, będę pisał dalej.

Pogłębiony rzut oka na problem

> EXPLAIN PLAN FOR SELECT * FROM abcd_test_table WHERE klucz = 'ABC3';
> SELECT PLAN_TABLE_OUTPUT FROM TABLE(DBMS_XPLAN.DISPLAY());

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------
Plan hash value: 3128743044

-----------------------------------------------------------------------------------------------
| Id  | Operation                   | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |                 |     1 |   289 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| ABCD_TEST_TABLE |     1 |   289 |     2   (0)| 00:00:01 |
|*  2 |   INDEX UNIQUE SCAN         | SYS_C0054064    |     1 |       |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - access("KLUCZ"='ABC3')

Ładny, prosty strzał po indeksie.

Ale:

> EXPLAIN PLAN FOR SELECT * FROM abcd_test_table WHERE klucz = N'ABC4';
> SELECT PLAN_TABLE_OUTPUT FROM TABLE(DBMS_XPLAN.DISPLAY());

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------
Plan hash value: 2006777524

-------------------------------------------------------------------------------------
| Id  | Operation         | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |                 |     1 |   289 |  4462   (2)| 00:00:54 |
|*  1 |  TABLE ACCESS FULL| ABCD_TEST_TABLE |     1 |   289 |  4462   (2)| 00:00:54 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter(SYS_OP_C2C("KLUCZ")=U'ABC4')

Co się dzieje pod spodem

W powyższym planie widać, że Oracle cichaczem zamienił sobie

WHERE klucz = N'ABC4'

na

WHERE SYS_OP_C2C("KLUCZ") = U'ABC4'

W związku z tym indeks po KLUCZ przestał być do czegokolwiek przydatny, próby wymuszania jego użycia w najlepszym wypadku prowadziły do full-index scanu.

Indeks funkcyjny po SYS_OP_C2C("KLUCZ") też sam z siebie używany nie był ale po dodaniu hinta nakazującego jego użycie, pomógł.

Funkcja SYS_OP_C2C jest wewnętrzną funkcją Oracle służącą do konwersji „varchar → nchar” (czyli zbliżoną do TO_NCHAR).

    select dump('ab'), dump(n'ab'), dump(sys_op_c2c(n'ab')) from dual;

    DUMP('AB')          DUMP(N'AB')             DUMP(SYS_OP_C2C(N'AB'))
    ------------------- ----------------------- -----------------------
    Typ=96 Len=2: 97,98 Typ=96 Len=4: 0,97,0,98 Typ=96 Len=2: 97,98

W tym wypadku Oracle przeprowadził zatem logikę w stylu „skoro przyszły do mnie dane w utf16, to skonwertuję wartość kolumny z «jakakolwiek jest» do utf16 by w w utf16 przeprowadzić porównanie”

Skąd wzięła się ta cała koncepcja? Nie wiem ale przypuszczam, że z zapytań takich, jak:

    SELECT * FROM table WHERE klucz < :parametr

w których semantyka < zależy od tego, w jakim kodowaniu się je prowadzi.

Czemu o przyjętym sortowaniu decyduje kodowanie wiązanego parametru a nie ustawienia językowe sesji – nie wiem i nie rozumiem.

Co miała do tego pythonowa aplikacja

Przypomnę cytowany już na początku kod:

query = abc_table.select()\
                 .where(abc_table.c.klucz == parametr)
result = db_session.execute(query)

Zależnie od tego, czym jest parametr, może on mieć dwa oblicza.

To działa szybko i nie sprawia problemów:

query = abc_table.select()\
                 .where(abc_table.c.klucz == 'ala ma kota')
result = db_session.execute(query)

To jest potwornie wolne i powoduje pełny skan:

query = abc_table.select()\
                 .where(abc_table.c.klucz == u'ala ma kota')
result = db_session.execute(query)

Jeśli ktoś nie zauważył, chodzi o pojedynczą literkę u. W pierwszym wypadku wiązanym parametrem jest stała „binarny pythonowy string” a w drugim „string unicode”.

Problem w aplikacji zaczął się gdy … pojawiły się dane zawierające polskie znaczki, bo takie jedna z wyższych warstw przekazywała dalej jako unicode.

W pierwszym wypadku, SQLAlchemy+cxOracle nie mają pojęcia czym jest wiązana wartość, więc wiąże ją as-is, jako „nieokreślony string”.

W drugim wypadku, SQLAlchemy+cxOracle same serializują napis do binarnego stringa, wiedzą więc w jakim jest on kodowaniu i … grzecznie informują o tym także driver Oracle. Technicznie chodzi o ustawienie informacji o kodowaniu parametru, zanurzone gdzieś głęboko w warstwie C wywołanie

    OCIAttrSet(OCI_ATTR_CHARSET_ID, ...)

dla danego wiązanego parametru. Innymi słowy: robią z grubsza to samo co w wariancie z „nieokreślonym” stringiem ale dodatkowo informują bibliotekę Oracle w jakim ten string jest encodingu.

I to wystarczy. Tak zbindowany parametr Oracle traktuje analogicznie jak stałe N'...' w powyższych ręcznych przykładach.

Rozwiązanie dla SQLAlchemy+cx_Oracle

Cóż, w żadnym wypadku nie przekazywać unicode jako wartości dynamicznie wiązanych parametrów. Dekodować je samodzielnie do binarnych stringów zgodnych z ustawionym dla bazy kodowaniem.

Nie tylko SQLAlchemy. Też NET, Java, ...

Po odkryciu o co chodziło udało nam się znaleźć informacje, że podobne problemy spotykali także programiści używający Javy czy .NET.