Mejorando la performance con binding con los nuevos Cursores Adaptables (Adaptive Cursors)

Todo aquel que haya asistido a un curso de sql o haya leido libros o documentación relacionada con "binding de variables" ya sabrá que es un concepto muy vinculado con el rendimiento de aplicaciones. En especial en los sistemas OLTP se recomienda fuertemente utilizar variables bind en las sentencias para evitar el hard parsing y asi minimizar la utilización de shared pool y obtener una mejor performance al saltear la etapa de parseo en la ejecuciones sucesivas a la primera ejecución de una sentencia dada.

El hecho de "bindear" si bien esta circunscripto dentro de las buenas prácticas tambien tiene ciertos problemas ya que no se conoce que valores se usaran para instanciar las variables bind y no queda claro para el optimizador que plan armar. A partir de 9i existe un mecanismo denominado "bind peeking" que permite al optimizador conocer los valores de la primera instanciación y por lo tanto armar un plan concreto. Esta nueva caracteristica introdujo nuevos problemas. El binding y los histogramas no se llevan del todo bien. Recordemos que los histogramas ayudan al optimizador ya que le proveen de la distribución de los datos.

Como dije antes, al bindear el optimizador no conoce de antemano con que valor se instanciará cada variable bind y por lo tanto no permite adecuar el plan a los valores de entrada. Si la distribución de los datos es uniforme esto no es un problema, pero que pasa si la distribución es dispar?. Que sucede si en la primera instanciación se genera un plan para usar full scan debido a que el valor de entrada tiene baja selectividad y luego las siguientes instanciaciones de valores tienen alta selectividad?. Estos ultimos generalmente requieren acceso por indices, pero el plan quedó fijado con la primera instanciación y por lo tanto usará full scan cuando en realidad debió usar acceso por indice, imaginense lo complicado que puede resultar esto. Por ejemplo, una mañana un programador ejecuta una consulta que instancia con un valor de borde o poco común para hacer un reporte complejo que recorre un porcentaje alto de filas y queda armado un plan con acceso full scan sobre una tabla grande, luego, si el cursor sigue en memoria, las aplicaciones usarán el mismo cursor para busquedas puntuales y usaran el plan generado por la consulta extraña (que usó full scan), suena caótico, no?.

En 11g R1 se agregó una nueva caracteristicas llamada "adaptive cursors" que soluciona el problema de "bind peeking". A continuación les muestro unas pruebas que realicé:

Para el test voy a crear una tabla sencilla con dos columnas X e Y. La columna Y tiene 3 posibles valores (A,B y C). Donde A tiene muy baja selectividad, B tiene selectividad media y C tiene selectividad alta.

rop@DESA11G> create table t (x int, y char(1))
  2  pctfree 90;
Tabla creada.

Cree la tabla T con pctfree en 90% para que se generen muchos bloques con no tantas filas.

rop@DESA11G> insert into t 
  2  select t_seq.nextval,
  3         case when (rownum between 1 and 4000000) then 'A'
  4              when (rownum between 4000001 and 5000000) then 'B'
  5              when (rownum between 5000001 and 5000010) then 'C'
  6         end
  7  from dual
  8  connect by rownum <= 5000010;

5000010 filas creadas.

rop@DESA11G> select bytes,blocks from user_segments where segment_name = 'T';

     BYTES     BLOCKS
---------- ----------
 679477248      82944

Generé una tabla que pesa mas de 600Mb.
Ahora creo un indice, recolecto estaditicas

rop@DESA11G> create index t_idx on t(y);

Índice creado.

rop@DESA11G>   begin
  2        dbms_stats.gather_table_stats(ownname => user,
  3                                      tabname => 'T',
  4                                      method_opt => 'for all indexed columns',
  5                                      cascade => true) ;
  6    end;
  7  /

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> select y,count(1)
  2          from t
  3          group by y;

Y   COUNT(1)
- ----------
A    4000000
B    1000000
C         10

En la ultima consulta se ve la distribución de la columna Y en la tabla T.

Voy a ejecutar una consulta y la voy a instanciar la variable bind :v con el valor 'A' para que se arme un plan que utilice full_scan:

rop@DESA11G> variable v char(1);
rop@DESA11G> exec :v:= 'A';

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> set autotr on
rop@DESA11G> select avg(x) from t where y = :v;

    AVG(X)
----------
21640320.5


Plan de Ejecución
----------------------------------------------------------
Plan hash value: 1842905362

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |     7 | 22533   (1)| 00:04:31 |
|   1 |  SORT AGGREGATE    |      |     1 |     7 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |  1666K|    11M| 22533   (1)| 00:04:31 |
---------------------------------------------------------------------------

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

   2 - filter("Y"=:V)


Estadísticas
----------------------------------------------------------
        329  recursive calls
          0  db block gets
      82086  consistent gets
      82045  physical reads
          0  redo size
        243  bytes sent via SQL*Net to client
        233  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
          1  rows processed

El plan usó efectivamente full_scan. Notar la gran cantidad de lecturas fisicas.

Consultemos la vista V$SQL:

rop@DESA11G> select sql_id,child_number,is_bind_sensitive, is_bind_aware
  2  from v$sql
  3  where sql_text = 'select avg(x) from t where y = :v';

SQL_ID        CHILD_NUMBER IS_BIND_SENSITIVE    IS_BIND_AWARE
------------- ------------ -------------------- ---------------
d9p5ax32fmqdn            0 Y                    N

Como se observa, en 11g se agregaron nuevas columnas a la vista v$sql relativas a las variables bind.

Instanciemos Y := 'C', que tiene muy alta selectividad:

rop@DESA11G> exec :v:='C';

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> set autotr on
rop@DESA11G> select avg(x) from t where y = :v;

    AVG(X)
----------
24640325.5


Plan de Ejecución
----------------------------------------------------------
Plan hash value: 1842905362

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |     7 | 22533   (1)| 00:04:31 |
|   1 |  SORT AGGREGATE    |      |     1 |     7 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |  1666K|    11M| 22533   (1)| 00:04:31 |
---------------------------------------------------------------------------

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

   2 - filter("Y"=:V)


Estadísticas
----------------------------------------------------------
          0  recursive calls
          0  db block gets
      82037  consistent gets
      82025  physical reads
          0  redo size
        243  bytes sent via SQL*Net to client
        233  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

Usó full scan, para retornar solo 10 valores, observemos nuevamente las lecturas fisicas.

Voy a consultar nuevamente la vista v$sql:

rop@DESA11G> select sql_id,child_number,is_bind_sensitive, is_bind_aware
  2  from v$sql
  3  where sql_text = 'select avg(x) from t where y = :v';

SQL_ID        CHILD_NUMBER IS_BIND_SENSITIVE    IS_BIND_AWARE
------------- ------------ -------------------- ---------------
d9p5ax32fmqdn            0 Y                    N

Sigue igual que antes.
Vuelvo a repetir la consulta anterior:

rop@DESA11G> select avg(x) from t where y = :v;

    AVG(X)
----------
24640325.5


Plan de Ejecución
----------------------------------------------------------
Plan hash value: 1842905362

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |     7 | 22533   (1)| 00:04:31 |
|   1 |  SORT AGGREGATE    |      |     1 |     7 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |  1666K|    11M| 22533   (1)| 00:04:31 |
---------------------------------------------------------------------------

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

   2 - filter("Y"=:V)


Estadísticas
----------------------------------------------------------
          1  recursive calls
          0  db block gets
          4  consistent gets
          4  physical reads
          0  redo size
        243  bytes sent via SQL*Net to client
        233  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

El plan sigue marcando acceso full scan, pero observemos ahora las lecturas fisicas. Fueron solo 4!.

rop@DESA11G> set autotr off
rop@DESA11G> select sql_id,child_number,is_bind_sensitive, is_bind_aware
  2  from v$sql
  3  where sql_text = 'select avg(x) from t where y = :v';

SQL_ID        CHILD_NUMBER IS_BIND_SENSITIVE    IS_BIND_AWARE
------------- ------------ -------------------- ---------------
d9p5ax32fmqdn            0 Y                    N
d9p5ax32fmqdn            1 Y                    Y

La consulta ahora muestra otro sqlid que es hijo del original con la columna is_bind_aware en "Y". El último plan mostró full scan aunque no concuerda con las pocas lecturas físicas y lógicas, ya que el método que usé para obtener el plan (dbms_xplan.diplay no tiene la opción de indicar el child) no muestra el plan del child 1 sino solo el plan padre (child=0). Después voy a mostrar con un trace 10046 que efectivamente usó acceso por indice (tambien se puede hacer con dbms_xplan.display_cursor indicando el child), lo cual cierra con la poca cantidad de lecturas que necesitó.

Consultando las nuevas vistas de "adaptive cursors" se ve como Oracle lleva registro de las ejecuciones y se adapta automaticamente a los cambios abruptos de selectividad al instanciar las variables:

rop@DESA11G> select  child_number, 
  2  bind_set_hash_value, 
  3  peeked, 
  4  executions, 
  5  rows_processed, 
  6  buffer_gets, 
  7  cpu_time
  8  from v$sql_cs_statistics
  9  where sql_id ='d9p5ax32fmqdn';

CHILD_NUMBER BIND_SET_HASH_VALUE P EXECUTIONS ROWS_PROCESSED BUFFER_GETS   CPU_TIME
------------ ------------------- - ---------- -------------- ----------- ----------
           1          2477564004 Y          1             21           4          0
           0           816821622 Y          1        4000001       82086          0


rop@DESA11G> ed
Escrito file afiedt.buf

  1  select * from v$sql_cs_histogram
  2  where sql_id ='d9p5ax32fmqdn'
  3* order by child_number,bucket_id
rop@DESA11G> /

ADDRESS          HASH_VALUE SQL_ID        CHILD_NUMBER  BUCKET_ID      COUNT
---------------- ---------- ------------- ------------ ---------- ----------
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            0          0          1
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            0          1          0
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            0          2          1
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            1          0          3
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            1          1          0
000000044B9DC7B8 3303659956 d9p5ax32fmqdn            1          2          0

6 filas seleccionadas.

Registrando la actividad y midiendo internamente rapidamente se detectó que el plan no era adecuado y se cambió.

A continuación muestro el resultado de tracear con el evento 10046:

El cursor principal o padre:

********************************************************************************

SQL ID: d9p5ax32fmqdn
Plan Hash: 1842905362
select avg(x)
from
 t where y = :v


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.00       0.00          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        6     12.58      11.26     246075     246111          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12     12.58      11.26     246075     246111          0           3

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 82

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=82037 pr=82025 pw=0 time=0 us)
4000000   TABLE ACCESS FULL T (cr=82037 pr=82025 pw=0 time=19822 us cost=22641 size=28010066 card=4001438)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       6        0.00          0.00
  direct path read                             1956        0.23          1.58
  SQL*Net message from client                     6        0.00          0.04
********************************************************************************

El cursor hijo 1:

********************************************************************************

SQL ID: 804rjbx6snjv4
Plan Hash: 3178687684
select avg(x)
from
 t where y = :v


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          4          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       0.00          0          4          0           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 82

Rows     Row Source Operation
-------  ---------------------------------------------------
      1  SORT AGGREGATE (cr=4 pr=0 pw=0 time=0 us)
     10   TABLE ACCESS BY INDEX ROWID T (cr=4 pr=0 pw=0 time=0 us cost=4 size=7 card=1)
     10    INDEX RANGE SCAN T_IDX (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=1)(object id 83154)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  SQL*Net message from client                     2        0.00          0.01
********************************************************************************

Una vez mas vemos que versión tras versión se van agregando "correcciones" al optimizador por costos para minimizar el margen de error y estabilizar los sistemas.