Reporte para obtener métricas de SO desde AWR

Como podemos hace para detectar problemas de cpu o i/o sin tener que pedir ayuda al grupo de Sistemas Operativos?, suena complicado, no?. Bueno... a partir de 10g una opción, por lo menos para ir teniendo un primer panorama, es ver si esta pasando algo con la caja donde reside nuestra base de datos consultando en el repositorio AWR. Para exteriorizar estas métricas existe la vista historica: DBA_HIST_OSSTAT, que en 10g contiene lo siguiente:

STAT_NAME
-------------------------------------------
BUSY_TIME
AVG_IDLE_TIME
NUM_CPUS
AVG_BUSY_TIME
OS_CPU_WAIT_TIME
VM_IN_BYTES
AVG_USER_TIME
AVG_SYS_TIME
LOAD
SYS_TIME
RSRC_MGR_CPU_WAIT_TIME
IDLE_TIME
USER_TIME
PHYSICAL_MEMORY_BYTES
IOWAIT_TIME
AVG_IOWAIT_TIME
VM_OUT_BYTES

y en 11g R1 se agregan las siguientes:

TCP_SEND_SIZE_DEFAULT
TCP_RECEIVE_SIZE_DEFAULT
TCP_RECEIVE_SIZE_MAX
NUM_CPU_SOCKETS
TCP_SEND_SIZE_MAX
NUM_CPU_CORES


Abajo, les copio un script que armé para ver algunas métricas importantes. El reporte toma como unico parametro la cantidad de horas hacia atras que quiero analizar.

set line 120
set pagesize 9999
set verify off
accept horas prompt "Ingrese cantidad de horas hacia atras que desea reportar: "

col snap format a20

select unique to_char(snap,'DD-MON-YYYY HH24') snap,
       avg_idle_time-lead(avg_idle_time) over (partition by st order by snap desc) avg_idle_time,
       avg_user_time-lead(avg_user_time) over (partition by st order by snap desc) avg_user_time,
       avg_sys_time-lead(avg_sys_time) over (partition by st order by snap desc) avg_sys_time,
       avg_iowait_time-lead(avg_iowait_time) over (partition by st order by snap desc) avg_iowait_time,
       os_cpu_wait_time-lead(os_cpu_wait_time) over (partition by st order by snap desc) os_cpu_wait_time
from
(select s.end_interval_time snap,
        s.startup_time st,
       max(decode(stat_name,'AVG_IDLE_TIME',value,null)) AVG_IDLE_TIME,
       max(decode(stat_name,'AVG_USER_TIME',value,null)) AVG_USER_TIME,
       max(decode(stat_name,'AVG_SYS_TIME',value,null)) AVG_SYS_TIME,
       max(decode(stat_name,'AVG_IOWAIT_TIME',value,null)) AVG_IOWAIT_TIME,
       max(decode(stat_name,'OS_CPU_WAIT_TIME',value,null)) OS_CPU_WAIT_TIME
from dba_hist_osstat os,
     dba_hist_snapshot s
where s.snap_id = os.snap_id
group by s.end_interval_time,s.startup_time)
where snap > sysdate-&horas/24
order by snap desc
/


SNAP         AVG_IDLE_TIME AVG_USER_TIME AVG_SYS_TIME AVG_IOWAIT_TIME OS_CPU_WAIT_TIME
25-FEB-10 09 211854       108399     40156  99439  2087400
25-FEB-10 08 271995       61131     27296  97923  1199800
25-FEB-10 07 236760       85951     31938  84592  1489500
25-FEB-10 06 180172       130112     50168  90475  2281500
25-FEB-10 05 182995       123247     54623  105254  2274500
25-FEB-10 04 193166       116204     51902  127028  2197000
25-FEB-10 03 195871       119849     45241  130806  2126400
25-FEB-10 02 236610       85916     37782  160617  1574500

Obviamente, para tener un diagnostico preciso de uso de recursos de SO lo ideal es pedir a los grupos encargados de la administración del SO, networking o storage reportes detallados historicos de actividad, pero si queremos tener una primera foto en forma rapida de lo que esta pasando con solo tener acceso al repositorio de la base, podemos usar la consulta de arriba o cualquier variación (se puede agregar columnas para reportar uso de memoria virtual, tráfico de red, etc) de esta para tener una primera impresión.

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.

Compresión avanzada de Tablas en 11g (OLTP Compression)

En esta nota la idea es mostrarles algunas de las primeras pruebas que realicé sobre compresión de tablas. Uno de los features mas fervientemente presentados por Oracle en su última versión (11g) es justamente la compresión avanzada. Desde 9i se puede comprimir tablas pero con ciertas restricciones. En 9i y 10g la compresión de tablas la podriamos llamar básica ya que tiene varias limitaciones y la compresión solo aplica para un restringido set de operaciones (por ejemplo para el insert directo) lo que lo hace bastante util para sistemas DW pero no tanto para las bases OLTP.

Oracle 11g introdujo la compresión avanzada con el fin de reducir la utilización de recursos y la manipulación de grandes volúmenes de datos. Permite una sensible reducción del storage requerido para datos relacionales o estructurados (tablas), datos no estructurados (archivos) o datos de respaldo (backups).

El nuevo feature OLTP Table Compression usa un algoritmo diseñado para trabajar con aplicaciones OLTP. Dicho algoritmo trabaja eliminando valores duplicados a nivel de bloque. El ratio de compresión esperado es de 2 a 3 usando OLTP Compression. Lo más novedoso es que con este feature se puede leer la información comprimida sin necesidad de descomprimirla por lo tanto no existe degradación de rendimiento y hasta puede mejorar la performance debido a una reducción de I/O ya que se necesitará acceder menos bloques para obtener las mismas filas sumado con la consiguiente reducción de buffer cache requerido. De todas formas a mi me gusta ver para creer y por lo tanto les voy a mostrar mis pruebas para que uds saquen sus propias conclusiones, además de incentivarlos a tomar como práctica habitual testear siempre antes de implementar.

No tengo a mano en estos momentos una base R2 de 11g asi que mis pruebas se van a basar en R1. En R2 cambio la sintaxis pero la semántica de las operaciones es la misma que en R1. Por si alguno quisiera probar mi test en R2, y tiene pereza de consultar el manual SQL Reference, les paso las diferencias:

COMPRESS FOR ALL OPERATIONS         (11gR1) = COMPRESS FOR OLTP (11gR2)
COMPRESS FOR DIRECT_LOAD OPERATIONS (11gR1) = COMPRESS BASIC (11gR2)  (*)default

Para la prueba voy a crear 3 tablas:

T       : Sin Compresión
T_C_DSS : Compresión DSS o compresión básica (el mismo tipo de compresión de 
          versiones anteriores)
T_C_OLTP: Compresión avanzada (11g+)

Conectado a:
Oracle Database 11g Enterprise Edition Release 11.1.0.7.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

rop@ROP11G> create table t (x int,y char(30),z date);

Tabla creada.

rop@ROP11G> create table t_c_dss (x int,y char(30),z date) compress;

Tabla creada.

rop@ROP11G> create table t_c_oltp (x int,y char(30),z date) compress for all operations;

Tabla creada.

rop@ROP11G> select table_name,pct_free,compression,compress_for from user_tables
  2  where table_name in ('T','T_C_DSS','T_C_OLTP');

TABLE_NAME                       PCT_FREE COMPRESS COMPRESS_FOR
------------------------------ ---------- -------- ------------------
T                                      10 DISABLED
T_C_DSS                                 0 ENABLED  DIRECT LOAD ONLY
T_C_OLTP                               10 ENABLED  FOR ALL OPERATIONS

Consultando en el catálogo se puede ver el tipo de partición. Observar que el pctfree en dss es 0 ya que no se esperan cambios.
Ahora voy a insertarles 5M de filas en forma aleatoria pero buscando un forma de que se repitan muchas veces valores en las columnas para que se aproveche la compresión
La columna x insertará valores unicos, la columna y insertará letras A y B y la columna z insertará fechas de hasta 10 dias posteriores al test.

rop@ROP11G> set timing on
rop@ROP11G> set autotr on
rop@ROP11G> insert into t
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6  connect by rownum <= 5000000;

5000000 filas creadas.

Transcurrido: 00:02:57.65

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

-------------------------------------------------------------------------------
| Id  | Operation                      | Name | Rows  | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | INSERT STATEMENT               |      |     1 |     2   (0)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL       | T    |       |            |          |
|   2 |   COUNT                        |      |       |            |          |
|*  3 |    CONNECT BY WITHOUT FILTERING|      |       |            |          |
|   4 |     FAST DUAL                  |      |     1 |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------

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

   3 - filter(ROWNUM<=5000000)


Estadísticas
----------------------------------------------------------
       4918  recursive calls
     304059  db block gets
      67349  consistent gets
          5  physical reads
  292595868  redo size
        875  bytes sent via SQL*Net to client
        690  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          4  sorts (memory)
          0  sorts (disk)
    5000000  rows processed

rop@ROP11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.06
rop@ROP11G> insert into t_c_dss
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6  connect by rownum <= 5000000;

5000000 filas creadas.

Transcurrido: 00:02:48.43

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

----------------------------------------------------------------------------------
| Id  | Operation                      | Name    | Rows  | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------
|   0 | INSERT STATEMENT               |         |     1 |     2   (0)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL       | T_C_DSS |       |            |          |
|   2 |   COUNT                        |         |       |            |          |
|*  3 |    CONNECT BY WITHOUT FILTERING|         |       |            |          |
|   4 |     FAST DUAL                  |         |     1 |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------------

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

   3 - filter(ROWNUM<=5000000)


Estadísticas
----------------------------------------------------------
       4644  recursive calls
     276921  db block gets
      60593  consistent gets
          0  physical reads
  290874948  redo size
        875  bytes sent via SQL*Net to client
        696  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
    5000000  rows processed

rop@ROP11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.04

rop@ROP11G> insert into t_c_oltp
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6  connect by rownum <= 5000000;

5000000 filas creadas.

Transcurrido: 00:08:58.00

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

-----------------------------------------------------------------------------------
| Id  | Operation                      | Name     | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | INSERT STATEMENT               |          |     1 |     2   (0)| 00:00:01 |
|   1 |  LOAD TABLE CONVENTIONAL       | T_C_OLTP |       |            |          |
|   2 |   COUNT                        |          |       |            |          |
|*  3 |    CONNECT BY WITHOUT FILTERING|          |       |            |          |
|   4 |     FAST DUAL                  |          |     1 |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------------

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

   3 - filter(ROWNUM<=5000000)


Estadísticas
----------------------------------------------------------
       7402  recursive calls
     450484  db block gets
      93862  consistent gets
          3  physical reads
  945961224  redo size
        877  bytes sent via SQL*Net to client
        697  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
    5000000  rows processed

Los tiempos de inserción convencional para cada tablas fueron:

T        = 2m 57s
T_C_DSS  = 2m 48s
T_C_OLTP = 8m 54s

El tiempo de inserción sobre la tabla oltp fue 3 veces mayor al de la tabla dss y la tabla común, pero lo mas llamativo es la cantidad de redo usado:

Redo Insert en T        =  292595868 ~=  279Mb  
Redo Insert en T_C_DSS  =  290874948 ~=  277Mb
Redo Insert en T_C_OLTP =  945961224 ~=  902Mb

También se observa que la cantidad de redo es de mas de 3 veces.
Busqué en metalink y la nota "COMPRESS FOR ALL OPERATIONS generates lot of redo [ID 829068.1]" declara que es esperable bastante más consumo de redo en las operaciones dml sobre una tabla con compresión avanzada (CA).

De todas formas, tarda mas pero veamos si comprimió y cuanto:

rop@ROP11G> select segment_name,blocks,round(bytes/1024/1024,2) Mb from user_segments
  2  where segment_name in ('T','T_C_DSS','T_C_OLTP');

SEGMENT_NAME                       BLOCKS         MB
------------------------------ ---------- ----------
T                                   35456        277
T_C_DSS                             31744        248
T_C_OLTP                            11264         88

El factor de compresión sobre la table T_C_OLTP fue importante comparado con las otras dos tablas. Tambien observamos que la relación de 3 se sigue manteniendo ya que la tabla oltp aloca 3 veces menos espacio que las tablas con compresión dss y sin compresión que alocaron espacio similar. Parece que sacrificando mayor consumo de redo y más tiempo de procesamiento del insert tuvo sus resultados, no?.

La próxima prueba será analizar los inserts directos. Recordemos que este tipo de insert es muy usado para carga masiva , en especial en sistemas Datawarehouse (ETL).
Voy a testear la inserción de 1M de filas:

rop@ROP11G> insert /*+ APPEND */ into t
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6  connect by rownum <= 1000000;

1000000 filas creadas.

Transcurrido: 00:00:29.37

  1  insert /*+ APPEND */ into t_c_dss
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6* connect by rownum <= 1000000
rop@ROP11G> /

1000000 filas creadas.

Transcurrido: 00:00:32.01
rop@ROP11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.07
rop@ROP11G> ed
Escrito file afiedt.buf

  1  insert /*+ APPEND */ into t_c_oltp
  2  select rownum ,
  3         chr(64+trunc(dbms_random.value(1,3))),
  4         trunc(sysdate)+trunc(dbms_random.value(1,10))
  5  from dual
  6* connect by rownum <= 1000000
rop@ROP11G> /

1000000 filas creadas.

Transcurrido: 00:00:30.01
rop@ROP11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.01

Con el insert directo los tiempos fueron similares:

T        = 29s
T_C_DSS  = 32s
T_C_OLTP = 30s

y el espacio alocado:

rop@ROP11G> ed
Escrito file afiedt.buf

  1  select segment_name,blocks,round(bytes/1024/1024,2) Mb from user_segments
  2* where segment_name in ('T','T_C_DSS','T_C_OLTP')
rop@ROP11G> /

SEGMENT_NAME                       BLOCKS         MB
------------------------------ ---------- ----------
T                                   48768        381
T_C_DSS                             33792        264
T_C_OLTP                            13312        104

De los resultados de arriba vemos que el insert directo incremento el espacio alocado de cada segmento de la siguiente manera:

SEGMENT_NAME                   deltha en Mb
------------------------------ -------
T                              104 (381-277)
T_C_DSS                        16  (264-248)
T_C_OLTP                       16  (104-88)

De estos resultados se deduce que la compresión avanzada y la basica funcionaron igual para los insert directos, ambas solo tuvieron que alocar 16Mb adicionales para acomodar 1M de filas nuevas. Sin embargo la tabla si compresión tuvo que alocar un 25% extra.

Otro punto que me interesa testear son los update's y ver como se comporta este tipo de operación en cada caso. Para probar esto voy a cambiar la columna en 50000 filas.

rop@DESA11G> update t set y='C' where y = 'B' and rownum <= 50000;

50000 filas actualizadas.

Transcurrido: 00:00:01.96

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

----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | UPDATE STATEMENT    |      | 50000 |  1562K| 11537   (3)| 00:02:19 |
|   1 |  UPDATE             | T    |       |       |            |          |
|*  2 |   COUNT STOPKEY     |      |       |       |            |          |
|*  3 |    TABLE ACCESS FULL| T    |  2443K|    74M| 11537   (3)| 00:02:19 |
----------------------------------------------------------------------------

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

   2 - filter(ROWNUM<=50000)
   3 - filter("Y"='B')

Note
-----
   - dynamic sampling used for this statement


Estadísticas
----------------------------------------------------------
        258  recursive calls
       1667  db block gets
       1436  consistent gets
       1028  physical reads
    7656052  redo size
        847  bytes sent via SQL*Net to client
        574  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
      50000  rows processed

rop@DESA11G> commit;

Confirmación terminada.

rop@DESA11G> ed
Escrito file afiedt.buf

  1* update t_c_dss set y='C' where y = 'B' and rownum <= 50000
rop@DESA11G> /

50000 filas actualizadas.

Transcurrido: 00:00:01.84

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

-------------------------------------------------------------------------------
| Id  | Operation           | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT    |         | 50000 |  1562K|  9285   (3)| 00:01:52 |
|   1 |  UPDATE             | T_C_DSS |       |       |            |          |
|*  2 |   COUNT STOPKEY     |         |       |       |            |          |
|*  3 |    TABLE ACCESS FULL| T_C_DSS |  2512K|    76M|  9285   (3)| 00:01:52 |
-------------------------------------------------------------------------------

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

   2 - filter(ROWNUM<=50000)
   3 - filter("Y"='B')

Note
-----
   - dynamic sampling used for this statement


Estadísticas
----------------------------------------------------------
        257  recursive calls
      51518  db block gets
        827  consistent gets
        890  physical reads
   15677976  redo size
        867  bytes sent via SQL*Net to client
        580  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
      50000  rows processed

rop@DESA11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.01
rop@DESA11G> ed
Escrito file afiedt.buf

  1* update t_c_oltp set y='C' where y = 'B' and rownum <= 50000
rop@DESA11G> /

50000 filas actualizadas.

Transcurrido: 00:01:09.89

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

--------------------------------------------------------------------------------
| Id  | Operation           | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT    |          | 50000 |  1562K|  3791   (8)| 00:00:46 |
|   1 |  UPDATE             | T_C_OLTP |       |       |            |          |
|*  2 |   COUNT STOPKEY     |          |       |       |            |          |
|*  3 |    TABLE ACCESS FULL| T_C_OLTP |  2814K|    85M|  3791   (8)| 00:00:46 |
--------------------------------------------------------------------------------

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

   2 - filter(ROWNUM<=50000)
   3 - filter("Y"='B')

Note
-----
   - dynamic sampling used for this statement


Estadísticas
----------------------------------------------------------
        411  recursive calls
    6153098  db block gets
    4894807  consistent gets
       1567  physical reads
   40901448  redo size
        868  bytes sent via SQL*Net to client
        581  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          7  sorts (memory)
          0  sorts (disk)
      50000  rows processed

rop@DESA11G> commit;

Confirmación terminada.

Transcurrido: 00:00:00.01

Los tiempos del update de la columna y en cada caso fueron:

           Tiempo   Redo   Db block gets
           ------   ----   -------------
T          1s        7Mb   1667
T_C_DSS    1s       15Mb   51518
T_C_OLTP   1m 9s    39Mb   6153098

Los tiempos en la tabla oltp para el update masivo son muy superiores con respecto a los tiempos de la misma operacion sobre las otras tablas. Intenté probar de realizar el mismo update pero con 1M de filas y si bien para las tablas t y dss los tiempos fueron de menos de 2 minutos para el caso de la tabla oltp no terminó y pasadas 2 horas tuve que matar la sesión. Lo probé 3 veces en dias distintos y en los tres casos tuve que suspender la ejecución.

En el ultimo test voy a ver como se comportan los select's. Para ver detalle voy a activar el trace 10046. La sentencia que armé recorre toda la tabla:

rop@DESA11G>  ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';

Sesión modificada.

Transcurrido: 00:00:00.07
rop@DESA11G> ed
Escrito file afiedt.buf

  1  select z,count(*),max(z)
  2  from t
  3* group by z
rop@DESA11G> /

Z           COUNT(*) MAX(Z)
--------- ---------- ---------
18-FEB-10     666293 18-FEB-10
17-FEB-10     665982 17-FEB-10
20-FEB-10     667869 20-FEB-10
16-FEB-10     666656 16-FEB-10
23-FEB-10     665526 23-FEB-10
19-FEB-10     666827 19-FEB-10
22-FEB-10     665960 22-FEB-10
21-FEB-10     666494 21-FEB-10
24-FEB-10     668393 24-FEB-10

9 filas seleccionadas.

Transcurrido: 00:00:09.89
rop@DESA11G> ed
Escrito file afiedt.buf

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

select z,count(*),max(z)
from t
group by z

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.02       0.01          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     10.33       9.55      41379      42190          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     10.35       9.57      41381      42192          0           9

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      9  HASH GROUP BY (cr=42190 pr=41379 pw=0 time=0 us cost=11949 size=44228052 card=4914228)
6000000   TABLE ACCESS FULL T (cr=42190 pr=41379 pw=0 time=29090 us cost=11414 size=44228052 card=4914228)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         2        0.00          0.00
  SQL*Net message to client                       2        0.00          0.00
  reliable message                                1        0.00          0.00
  enq: KO - fast object checkpoint                1        0.00          0.00
  direct path read                              334        0.00          0.02
  SQL*Net message from client                     2        0.02          0.02
********************************************************************************


select z,count(*),max(z)
from t_c_dss
group by z

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2     10.71      10.02      33071      33680          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4     10.72      10.04      33073      33682          0           9

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      9  HASH GROUP BY (cr=33680 pr=33071 pw=0 time=0 us cost=9723 size=46852029 card=5205781)
6000000   TABLE ACCESS FULL T_C_DSS (cr=33680 pr=33071 pw=0 time=0 us cost=9155 size=46852029 card=5205781)


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
  reliable message                                1        0.00          0.00
  enq: KO - fast object checkpoint                1        0.00          0.00
  direct path read                              270        0.01          0.02
  SQL*Net message from client                     2        0.02          0.02
********************************************************************************

select z,count(*),max(z)
from t_c_oltp
group by z

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.00          2          2          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      9.82       9.42      12852      13635          0           9
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      9.83       9.42      12854      13637          0           9

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

Rows     Row Source Operation
-------  ---------------------------------------------------
      9  HASH GROUP BY (cr=13635 pr=12852 pw=0 time=0 us cost=4271 size=50894532 card=5654948)
6000000   TABLE ACCESS FULL T_C_OLTP (cr=13635 pr=12852 pw=0 time=0 us cost=3651 size=50894532 card=5654948)


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
  reliable message                                1        0.00          0.00
  enq: KO - fast object checkpoint                1        0.00          0.00
  direct path read                              110        0.00          0.00
  SQL*Net message from client                     2        0.02          0.02

Los tiempos en resolver la consulta fueron:

T        = 9.57s
T_C_DSS  = 10.04s
T_C_OLTP = 9.42s

El select sobre la tabla oltp fue el que menos tiempo arrojó, demostrando que no hubo overhead por el tema de la compresión.

Como conclusión general se ve que para operaciones masivas los tiempos y el consumo de redo sobre la tabla oltp son importantes y hay que tenerlos en cuenta. Tambien consideremos que este mecanismo, tal cual su nombre lo infiere, esta pensado para bases oltp en donde no es común el cambio masivo, aunque tampoco es tan infrecuente en ciertos casos, ya que muchas bases hibridas se comportan como oltp (por ejemplo durante el dia) y por la noche se usan como DSS con importante procesamiento batch que generalmente produce cambios masivos de datos.

En el paper oficial: "Advanced Compression with Oracle 11g R2" dice que las escrituras puntuales no se comprimen en cada operación y que la compresión de todo el bloque se realiza en forma batch cuando se alcanza un umbral en el bloque. Seguramente por ese motivo en mi test los tiempos fueron excesivos ya que al insertar o modificar muchas filas se alcanzó el umbral en varios bloques disparando la compresión en vivo y sumando tiempo al procesamiento de la sentencia.

A mi siempre me gusta testear a fondo cada nuevo feature para ver si lo puedo recomendar a mis clientes ya que no todo lo que brilla es oro y a veces existen restricciones que lo hacen inaplicable en ciertos negocios. Además hay que considerar el tema economico, la compresión avanzada, a diferencia de la compresión básica que viene habilitada para usar con la licencia de Enterprise Edition, se paga como un opcional aparte y por lo tanto es un factor no menor que merece se analizado antes de implementar este nuevo feature.

Evolución de los mecanismos para Estabilizar Planes (graciosa comparación)

Mirando un ppt de una presentación de los nuevos features de 11g me gustó uno de los slides donde se hace una especie de parodia sobre la evolución de los mecanismos para estabilizar los planes de ejecución que se fueron agregando en las distintas versiones. Se refiere a Larry (Ellison) que es el fundador y dueño de Oracle comparandolo con Dios y la creación de la tierra. Me pareció muy gracioso, y seguramente van a entender la sutileza todos aquellos que estén en el mundillo Oracle, en especial los que nos dedicamos a temas de performance que muchas veces admiramos la forma en que trabaja el optimizador y otras, sinceramente no entendemos porque toma ciertas decisiones que lo llevan a armar un plan desastroso, en fin... ahi va la evolución de los mecanismos de estabilidad:


In the beginning was the RULE …
On the Second Day, Larry Created the CBO … (7)
On the Third Day, Larry Created the Hint … (7)
On the Fourth Day, Larry Created the Outline … (8)
… and Larry Saw That it Was Good
On the Fifth Day, Larry Created the Profile … (10g)
On the Sixth Day, Larry Created the Baseline (11g)

Colorear una sentencia sql (Colored SQL)

Muchos se preguntaran que significa "colorear un sentencia sql", verdad?. Lo que implica colorear es ni mas ni menos que marcar una sentencia identificandola por su sqlid, que es la identificación unica de una sentencia en la base da datos, para que los snapshots de AWR la incluyan en el repositorio y luego ser analizada. El repositorio de AWR almacena, entre otras cosas, las sentencias TOP, es decir las que mas consumieron entre dos snapshots, por default los snapshots se sacan cada hora, por lo que permite analizar por periodos de una hora. Si yo quisiera ver como se fue comportando una sentencia a lo largo de cierto tiempo pero dicha sentencia no esta dentro de las mas consumidoras no quedará registro y por lo tanto no se podrá analizar su actividad a posteriori. Para asegurar que se le siga el rastro a las ejecuciones de un sentencia, sin importar cuanto consume, a partir de 11g se la puede "colorear", veamos como es esto:

Armo una consulta bien sencilla, que obviamente no consumirá mucho y no quedará registrada en una base con una minima actividad:

rop@DESA11G> select 'TEST COLORED SQL' from dual;

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

Buscamos el sqlid asociado:

rop@DESA11G> set line 120
rop@DESA11G>  select sql_text,sql_id from v$sqlstats where sql_text like '%TEST COLORED SQL%';

SQL_TEXT
------------------------------------------------------------------------------------------------------------------------
SQL_ID
-------------
 select sql_text,sql_id from v$sqlstats where sql_text like '%TEST COLORED SQL%'
f2c39t3uct6vp

select 'TEST COLORED SQL' from dual
0fm46pj2s9vux

Una vez obtenido el sqlid voy a marcarla o colorearla de la siguiente forma:

rop@DESA11G> ed
Escrito file afiedt.buf

  1  begin
  2    dbms_workload_repository.add_colored_sql(sql_id => '0fm46pj2s9vux'
  3    );
  4* end;
rop@DESA11G> /

Procedimiento PL/SQL terminado correctamente.

Ahora tomo un snapshot y luego ejecuto 3 veces la sentencia coloreada:

rop@DESA11G> begin
  2      dbms_workload_repository.create_snapshot;
  3  end;
  4  /

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> select 'TEST COLORED SQL' from dual;

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

rop@DESA11G> /

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

rop@DESA11G> /

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

Tomo otro snapshot luego de aproximadamente 15' y veo si aparece:

rop@DESA11G> begin
  2      dbms_workload_repository.create_snapshot;
  3  end;
  4  /

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> select executions_delta,cpu_time_delta,elapsed_time_delta from dba_hist_sqlstat
  2  where snap_id = (select max(snap_id) from dba_hist_sqlstat)
  3    and sql_id = '0fm46pj2s9vux';

EXECUTIONS_DELTA CPU_TIME_DELTA ELAPSED_TIME_DELTA
---------------- -------------- ------------------
               3              0                  0

La sentencia apareció y se ve que consumió tan poco que no se llegó a registrar tiempo
Para desmarcarla hago lo siguiente:

rop@DESA11G> ed
Escrito file afiedt.buf

  1  begin
  2    dbms_workload_repository.remove_colored_sql(sql_id => '0fm46pj2s9vux');
  3* end;
rop@DESA11G> /

Procedimiento PL/SQL terminado correctamente.

Repito el proceso pero sin la consulta "coloreada":

rop@DESA11G> ed
Escrito file afiedt.buf

  1  begin
  2      dbms_workload_repository.create_snapshot;
  3* end;
rop@DESA11G> /

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> select 'TEST COLORED SQL' from dual;

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

rop@DESA11G> /

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

rop@DESA11G> /

'TESTCOLOREDSQL'
----------------
TEST COLORED SQL

rop@DESA11G> begin
  2      dbms_workload_repository.create_snapshot;
  3  end;
  4  /

Procedimiento PL/SQL terminado correctamente.

rop@DESA11G> ed
Escrito file afiedt.buf

  1  select executions_delta,cpu_time_delta,elapsed_time_delta from dba_hist_sqlstat
  2  where snap_id = (select max(snap_id) from dba_hist_sqlstat)
  3*   and sql_id = '0fm46pj2s9vux'
rop@DESA11G> /

ninguna fila seleccionada

rop@DESA11G> 

Como se observa ahora no se registró en AWR, ya que como se vió es una sentencia con consumo nulo y que obviamente no califica entre las Top para ser persistida en el repositorio.

Extendiendo la información estadistica en 11g (estadisticas multicolumna)

Una vez mas escribo una nota relacionada con el optimizador de Oracle y en especial sobre las estadisticas, que como ya se sabe son el pilar fundamental para garantizar un plan optimo. Asi como un matematico se basa en axiomas o teoremas para demostrar otro teorema en base a inferencias logicas, el optimizador utiliza la información estadistica que tiene a su disposición para inferir el plan de ejecución mas conveniente, el que menos recurso insume. En 11g se pueden suministrar extensiones a las estadisticas habituales para "ayudar" en ciertos casos particulares. Uno de los problemas que se daban esta relacionado con la correlación entre la información estadisticas de multiples columnas que se referencian en un predicado. Para entender mejor voy a mostrar un ejemplo completo (en una nota de diciembre habia escrito sobre estaditicas multicolumnas para mostrar SQL Profiles, pero esta nueva nota ahonda en mas detalle, ver nota: SQL Profiles. Una ayuda adicional...)

Primero, como es habitual, voy a crear una tabla T en base a los registros de la tabla DBA_OBJECTS y voy a crear un indice por dos columnas elegidas arbitrariamente:

rop@DESA11G> create table t as select * from dba_objects;

Tabla creada.

rop@DESA11G> create index t_idx on t(owner,object_type);

Índice creado.

rop@DESA11G>

Ahora vamos a ver la distribución de las columnas OWNER y OBJECT_TYPE:

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

OWNER                            COUNT(1)
------------------------------ ----------
PUBLIC                              26723
SYSTEM                                518
XDB                                   811
OLAPSYS                               720
FLOWS_FILES                            12
SYS                                 30217
TSMSYS                                  3
MDSYS                                1303
SYSMAN                               3360
EXFSYS                                303
SI_INFORMTN_SCHEMA                      8
ORACLE_OCM                              8
WMSYS                                 315
ORDSYS                               2353
SCOTT                                   6
WK_TEST                                47
FLOWS_030000                         1526
CTXSYS                                372
ORDPLUGINS                             10
WKSYS                                 371
ROP                                   122
OUTLN                                   9
DBSNMP                                 55

23 filas seleccionadas.

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

OBJECT_TYPE           COUNT(1)
------------------- ----------
INDEX                     3228
JOB CLASS                   13
CONTEXT                      7
TABLE SUBPARTITION          40
TYPE BODY                  238
INDEXTYPE                   11
PROCEDURE                  135
RESOURCE PLAN                7
RULE                         1
JAVA CLASS               22205
TABLE PARTITION            289
SCHEDULE                     2
WINDOW                       9
WINDOW GROUP                 4
JAVA RESOURCE              835
TABLE                     2576
TYPE                      2643
VIEW                      4788
LIBRARY                    181
FUNCTION                   296
TRIGGER                    484
PROGRAM                     18
MATERIALIZED VIEW            1
JAVA SOURCE                  1
CLUSTER                     10
SYNONYM                  26795
PACKAGE BODY              1213
CONSUMER GROUP              14
EVALUATION CONTEXT          11
QUEUE                       35
RULE SET                    17
DIRECTORY                    3
EDITION                      1
OPERATOR                    57
UNDEFINED                    6
JAVA DATA                  325
SEQUENCE                   230
LOB                        768
PACKAGE                   1274
INDEX PARTITION            289
LOB PARTITION                7
JOB                         11
XML SCHEMA                  94

43 filas seleccionadas.

De la distribución mostrada podemos ver que tenemos 30210 filas cuyo owner es SYS y 26795 cuyo object_type es SYNONYM. Analizando por separadas ambas distribuciones vemos que son un porcentaje alto del total de cada agrupación y evaluadas por separado suena coherente el acceso full scan cuando se filtra por dichas columnas para los valores analizados.
Ahora veamos que pasa si en un mismo predicado filtramos por owner y object_type:

rop@DESA11G> select count(1) from t where owner = 'SYS' and object_type = 'SYNONYM';

COUNT(1)
----------
      9

Observamos que combinando las dos columnas solo cumplen dicho filtro 9 filas.
Voy a recolectar estadisticas y analizar el plan:

rop@DESA11G> begin
2             dbms_stats.gather_table_Stats(user,
3                              'T',
4                              method_opt => 'for all columns size skewonly');
5* end;
rop@DESA11G> /

rop@DESA11G> explain plan for
2          select *
3          from t
4          where owner = 'SYS' and object_type = 'SYNONYM';

Explicado.

rop@DESA11G> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------------
Plan hash value: 2153619298

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      | 11996 |  1183K|   288   (2)| 00:00:04 |
|*  1 |  TABLE ACCESS FULL| T    | 11996 |  1183K|   288   (2)| 00:00:04 |
--------------------------------------------------------------------------

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

1 - filter("OBJECT_TYPE"='SYNONYM' AND "OWNER"='SYS')

13 filas seleccionadas.

Estimó 11996 lo cual es muy impreciso, no?, deberia ser 9 o cercano para se mas real. Por que se confundió tanto el optimizador y eligió ir por full scan?. Miremos la salida del trace con el evento 10053, que nos muestra en detalle los pasos que sigue el optimizador para decidir que hacer. Abajo copio solo la parte del trace que nos interesa (el trace completo es muy extenso y lista parametrizaciones, transformaciones,orden de evaluación de predicados, etc):

***************************************
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for T[T]
Column (#1):
 NewDensity:0.000091, OldDensity:0.000007 BktCnt:5480, PopBktCnt:5478, PopValCnt:16, NDV:23
Column (#6):
 NewDensity:0.000091, OldDensity:0.000007 BktCnt:5480, PopBktCnt:5475, PopValCnt:26, NDV:43
ColGroup (#1, Index) T_IDX
 Col#: 1 6    CorStregth: 3.96
ColGroup Usage:: PredCnt: 2  Matches Full:  Partial:
Table: T  Alias: T
 Card: Original: 69172.000000  Rounded: 11646  Computed: 11645.63  Non Adjusted: 11645.63
 Access Path: TableScan
 Cost:  288.43  Resp: 288.43  Degree: 0
   Cost_io: 285.00  Cost_cpu: 31622103
   Resp_io: 285.00  Resp_cpu: 31622103
ColGroup Usage:: PredCnt: 2  Matches Full:  Partial:
ColGroup Usage:: PredCnt: 2  Matches Full:  Partial:
Access Path: index (AllEqRange)
 Index: T_IDX
 resc_io: 559.00  resc_cpu: 11318715
 ix_sel: 0.168358  ix_sel_with_filters: 0.168358
 Cost: 560.23  Resp: 560.23  Degree: 1
Best:: AccessPath: TableScan
      Cost: 288.43  Degree: 1  Resp: 288.43  Card: 11645.63  Bytes: 0

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

En el análisis el optimizador asigna un costo de 560 al plan que utiliza el indice y 288 al plan que utiliza el full scan, y como ya sabemos se queda con el que menor costo arroja, por lo tanto estima que es el mejor path.

Afortunadamente en 11g se pueden recolectar estadisticas a nivel multicoluma lo cual aporta información de correlación muy util, veamos como hacerlo:

rop@DESA11G> declare
2      out varchar2(30);
3  begin
4      out := dbms_stats.create_extended_stats(user,'T', '(owner,object_type)');
5  end;
6  /

rop@DESA11G> begin
2      dbms_stats.gather_table_stats(null,'T',
3      method_opt =>'for all columns size auto for columns (owner,object_type)');
4  end;
5  /

rop@DESA11G> explain plan for
2  select *
3  from t
4  where owner = 'SYS' and object_type = 'SYNONYM';

Explicado.

rop@DESA11G> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
Plan hash value: 1020776977

-------------------------------------------------------------------------------------
| Id  | Operation                   | Name  | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |       |     6 |   636 |     2   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T     |     6 |   636 |     2   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | T_IDX |     6 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------

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

2 - access("OWNER"='SYS' AND "OBJECT_TYPE"='SYNONYM')

14 filas seleccionadas.

El plan ahora uso el indice y ademas observar que la estimación de filas a retornar es de 6, lo cual es bastante cercano a la realidad. Veamos el trace del evento 10053 para analizar que hizo ahora el optimizador:

***************************************
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for T[T]
Column (#1):
 NewDensity:0.000091, OldDensity:0.000007 BktCnt:5480, PopBktCnt:5478, PopValCnt:16, NDV:23
Column (#6):
 NewDensity:0.000091, OldDensity:0.000007 BktCnt:5480, PopBktCnt:5475, PopValCnt:26, NDV:43
Column (#16):
 NewDensity:0.000091, OldDensity:0.000007 BktCnt:5480, PopBktCnt:5441, PopValCnt:104, NDV:250
ColGroup (#1, VC) SYS_STUXJ8K0YTS_5QD1O0PEA514IY
 Col#: 1 6    CorStregth: 3.96
ColGroup Usage:: PredCnt: 2  Matches Full:   Using density: 0.000091 of col #16 as selectivity of unpopular value pred
#1  Partial:  Sel: 0.0001
Table: T  Alias: T
 Card: Original: 69172.000000  Rounded: 6  Computed: 6.31  Non Adjusted: 6.31
Access Path: TableScan
 Cost:  288.20  Resp: 288.20  Degree: 0
   Cost_io: 285.00  Cost_cpu: 29526903
   Resp_io: 285.00  Resp_cpu: 29526903
ColGroup Usage:: PredCnt: 2  Matches Full:   Using density: 0.000091 of col #16 as selectivity of unpopular value pred
#1  Partial:  Sel: 0.0001
ColGroup Usage:: PredCnt: 2  Matches Full:   Using density: 0.000091 of col #16 as selectivity of unpopular value pred
#1  Partial:  Sel: 0.0001
Access Path: index (AllEqRange)
 Index: T_IDX
 resc_io: 2.00  resc_cpu: 19503
 ix_sel: 0.000091  ix_sel_with_filters: 0.000091
 Cost: 2.00  Resp: 2.00  Degree: 1
Best:: AccessPath: IndexRange
Index: T_IDX
      Cost: 2.00  Degree: 1  Resp: 2.00  Card: 6.31  Bytes: 0

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

El costo del full scan sigue siendo, obviamente, el mismo (288) pero ahora el acceso por indice es de tan solo 2 y por lo tanto es el path elegido.
Como les mostré en esta nota podemos garantizar un correcto funcionamiento para predicados con mas de un filtro recolectando las estadisticas extendidas, nuevas en 11g.