SQL Trace y TKPROF

• Aunque el EXPLAIN PLAN es una herramienta útil, posee limitantes.

• Por ejemplo, no da o da poca información sobre los recursos empleados por la consulta (tiempo de CPU, bloques procesados (disco y memoria), entre otros)

• Para ello se puede acudir a otras dos herramientas que actúan en conjunto: SQL Trace y TKPROF (Transient Kernel Profile, herramienta para dar formato al archivo generado por el SQL Trace)

SQL Trace

SQL Trace permite rastrear (trace) las sentencias SQL ejecutadas durante una sesión, almacenándolas en un archivo específico*.

En este archivo se guardan varios datos de interés para los analistas de las sentencias, tales como:

• tiempos de CPU,

• número de bloques procesados (I/O),

• estadísticas sobre parsing (análisis sintáctico),

• número de registros procesados, entre otros.

* Usualmente, estos archivos de rastreo tienen extensión trc

SQL Trace

El archivo generado por el SQL Trace es prácticamente imposible de interpretar directamente. Esto se puede comprobar abriendo el archivo con cualquier editor de texto. Ejemplo:

SQL Trace

Debido a lo anterior, se usa una herramienta que toma como entrada el archivo de rastreo y genera un archivo con información comprensible.

Esta herramienta (proporcionada también por Oracle) es el TKPROF

Pasos a seguir para usar SQL Trace y TKPROF:

1. Habilitar el SQL Trace

2. Localizar el archivo de rastreo de interés

3. Usar el TKPROF

4. Interpretar los resultados

5. Afinar la sentencia y repetir el proceso si es necesario

A continuación se explica cada uno de los pasos

1. Habilitar el SQL Trace

Para habilitar el rastreo de las sentencias, se ejecuta el siguiente comando desde SQL*PLUS (requiere: GRANT ALTER SESSION TO username):

ALTER SESSION SET SQL_TRACE = TRUE;OALTER SESSION SET SQL_TRACE TRUE;

Para activarlo desde PL/SQL se puede usar:

DBMS_SESSION.SET_SQL_TRACE(TRUE);

2. Localizar el archivo de rastreo de interés

El siguiente paso es buscar el archivo generado por el SQL Trace.

Estos archivos de rastreo (.trc) se guardan generalmente en la ruta que tiene el parámetro de configuración:

user_dump_dest

El nombre de los archivos generados tiene la siguiente nomenclatura:

header_pid.trc

Donde header es usualmente “ORA”, “XE_ORA”, “Oracle_SID_ORA”, o “SID_ORA” y el pid es el identificador que Oracle asigna al proceso.

Para hallar la ruta (ruta_d) donde se encuentran los archivos de rastreo, se puede ejecutar la siguiente consulta:

SELECT value AS ruta_dFROM v$parameter WHERE name = 'user_dump_dest';

Nota: Se requiere permiso para consultar esta vista o acudir al DBA:conn sys AS sysdba, ingresar la contraseña y hacer la consulta.

Para encontrar un archivo de rastreo específico, es necesario conocer cual fue el pid (process id) que Oracle asignó. Esto se puede averiguar mediante la siguiente consulta:

SELECT spid FROM sys.v_$processWHERE addr = (SELECT paddr FROM sys.v_$session WHERE audsid = USERENV('sessionid') );

Si se quiere personalizar el directorio donde se guardarán los archivos de rastreo, se puede hacer lo siguiente:

ALTER SYSTEM SET user_dump_dest = 'ruta_de_directorio';

Nota: el cambio se debe hacer antes de habilitar el rastreo de sentencias.

Requiere permisos: conn sys AS sysdba y dar GRANT SELECT al usuario sobre estas vistas

3. Usar el TKPROF

Una vez se encuentra el archivo de rastreo requerido, se usa el TKPROF para transformarlo en una forma interpretable. La sintaxis esencial es:

tkprof trace_file output_file [explain=username/password] sort(sort options)]

TKPROF, se ejecuta por fuera del entorno de SQL*PLUS, es decir, en una línea de comandos del sistema operativo:

C:\ruta_d> tkprof archivo.trc C:\temp\archivosalida.txt

A continuación se explican los parámetros del TKPROF.

Se debe tener permiso en el directorio de salida

Parámetros del TKPROF

trace_file Nombre del archivo generado por SQL Trace

output_file Nombre del archivo generado por TKPROF

explain=username/password Opcional. Especifica la conexión que será usada para generar los planes de ejecución.

sort=(sort keys) Opcional. Genera las sentencias SQL ordenadas según las claves elegidas (sort keys), ver a continuación.

Claves (keys) del ordenamiento del TKPROF: Cada clave de ordenamiento, se compone de dos partes:

• la primera indica la fase (tipo de llamada call) y

• la segunda parte indica el valor por el cual debe ordenar.

A continuación se presenta una tabla con las opciones

Primera parte (call)

prs Ordena sobre valores correspondientes a la fase de parsing.

exe Ordena sobre valores correspondientes a la fase de ejecución.

fch Ordena sobre correspondientes a la fase de fetch.

Segunda parte

cnt Número de llamadas.

cpu Consumo de CPU.

ela Tiempo transcurrido (elapsed time).

dsk Lecturas de disco.

qry Lecturas consistentes.

cu Lecturas actuales (current).

mis Library cache misses (aplica solo para parsing).

row Filas procesadas (aplica solo para exe y fch).

Ejemplo:

• Exedsk: Indica que las sentencias serán ordenadas en el archivo de salida según las lecturas de disco para la fase de ejecución.

C:\ruta_d> tkprof archivo.trc C:\temp\archivo.txt sort=EXEDSK;

4. Interpretar los resultados.

Estadísticas tabuladas: TKPROF lista las estadísticas en filas y columnas para una sentencia SQL. Las filas corresponden a las tres fases (calls) del procesamiento de una sentencia SQL:

PARSE(a): se traduce la sentencia SQL en un plan de ejecución, se verifica la existencia de objetos, permisos, etc.

EXECUTE(b): se ejecuta la sentencia. Para sentencias INSERT, UPDATE, y DELETE, en esta fase se modifican los datos. Para sentencias SELECTs, se preparan las filas para la fase de FETCH.

FETCH(c): se retornan las filas de la consulta. Estos “fetches” solo se hacen para sentencias SELECT.

call count cpu elapsed disk query current rows--------- ------- ------ ------- ------ ------ -------- ------Parse(a) (d) -- -- -- -- -- 0Execute(b) (e) -- -- -- -- -- (n)Fetch(c) (j) -- -- -- -- -- (i)--------- ------- ------ ------- ------ ------ -------- ------Total --- (l) (m) (k) (f) (g) (h)

Para sentencias SELECTs

En especial para sentencias INSERT, UPDATE y DELETE

COUNT((d), (e), (j)): El número de veces que cada tipo de call fue hecho.

CPU(l): Tiempo de CPU (segundos) requerido.

ELAPSED(m): Tiempo transcurrido («wall clock», en segundos).

DISK(k): Número total de bloques de datos leídos físicamente de los archivos de datos en el disco (physical I/Os).

QUERY(f): Número total de buffers leídos para las sentencias SELECT. Se les denomina buffers leídos en modo consistente (consistent mode).

CURRENT(g): Número total de buffers leídos para las sentencias que implican modificaciones (UPDATE, DELETE e INSERT). Se les denomina buffers leídos en modo current.*

Rows(h): Número total de filas procesadas. Para las sentencias SELECT, aplica para la fase de fetch. Para las sentencias UPDATE, DELETE, e INSERT, aplica para la fase de ejecución. (No se incluyen filas procesadas por subconsultas).

La suma de los totales de query y current (f) + (g) es el total de buffers leídos y se les suele llamar LIOs (logical I/Os).

* En un SELECT pueden ocurrir (lecturas del estado actual del dicc. de datos)

Tasas de Importancia

1. LIOs (f+g) sobre filas procesadas (h). Indica, de manera general, el costo relativo de la consulta. Mientras más buffers tienen que ser accedidos con relación a las filas retornadas, la fila retornada será mucho más costosa.

Tasas por encima de 10 o 20, pueden indicar alguna posibilidad de optimización en esta tasa.

Se pasa entonces a analizar algunas tasas que ayudarán a determinar que consultas SQL necesitan ser optimizadas.

2. Parsing (d) sobre ejecución (e). Idealmente, el conteo de parsing debe ser cercano a uno. Si este valor es alto con relación al conteo de ejecuciones, la sentencia ha sido analizada sintácticamente varias veces innecesariamente*.

3. Filas retornadas (i) sobre traídas** (fetches) (j) Indica el nivel en el que el array fetch ha sido usado. Una tasa cercana a uno indica que hubo poco procesamiento a través de arrays, lo que significa una posibilidad para optimizar este aspecto.

* Posibles causas: no uso de bind variables, pobre reuso de cursores.

** En cada traída (fetch) se recuperan múltiples filas usando un “array fetch”. Se debe buscar un valor adecuado para él dependiendo de las características del sistema. Ver Adjusting Array Size in SQL*Plus. SET ARRAYSIZE n (n entre 1 y 5000)

Tasas de Importancia

4. Lecturas de disco (k) sobre LIOs (f+g). Esta es una medida de la tasa de error (miss rate) dentro del buffer de datos en la cache. Usualmente, se busca que esta tasa esté por debajo de 10%.

Para mejorar algunas de las tasas se puede usar reescritura de las sentencias, índices, bind variables, reuso de cursores, ajuste del array fetch, afinamiento de diversos parámetros del servidor de la base de datos, entre otros aspectos que van más allá de esta introducción…

Recuerde: TKPROF indica donde puede haber un problema, no cómo solucionarlo

Tasas de Importancia

Por ejemplo:

- Si el total de rows (h) es bajo con relación al total de bloques procesados (physical y logical I/Os (k), (f), (g)), esto indica que se leyeron muchos bloques/buffers para generar un resultado con pocas filas Esto podría sugerir una oportunidad para optimizar

- Una gran diferencia entre el tiempo de CPU y el tiempo transcurrido (elapsed), es decir, (l) << (m) puede indicar que la sentencia estuvo esperando «algo», por ejemplo, un recurso bloqueado por otra sentencia.

Ejemplo de una bind variable en SQL*Plus:

SQL> variable deptno number

SQL> exec :deptno := 10

SQL> select * from emp where deptno = :deptno;

La idea clave es que la sentencia con la bind variable no requiere ser recompilada

así el valor de la bind variable cambie

Supóngase la siguiente consulta SQL:

SELECT DISTINCT e.apellido, e.nombre, e.fecha_nacimiento FROM empleado e WHERE EXISTS (SELECT * FROM cliente c WHERE e.apellido = c.apellido AND e.nombre = c.nombre AND e.fecha_nacimiento = c.fecha_nacimiento)ORDER BY e.apellido, e.nombre;

Salida del TKPROF: call count cpu elapsed disk query current rows--------- ------- ------ ------- ------ ------ -------- ------Parse 1 0 0.43 0 0 0 0Execute 1 0 0.00 0 0 0 0Fetch 11 0 323.74 204161 212083 2400 151--------- ------- ------ ------- ------ ------ -------- ------Total 13 0 324.17 204161 212083 2400 151

TASA VALOR RECOMENDADO

VALOR ENCONTRADO

(f+g) / h Entre 10 y 20 1420 aprox.

d / e 1 (o cerca de 1)

1

i / j > 1 13.73

k / (f+g) Menos de 10%

95%

Se ensaya reformulando la consulta así:

SELECT DISTINCT e.apellido, e.nombre, e.fecha_nacimiento FROM empleado e, cliente c WHERE e.apellido = c.apellido AND e.nombre = c.nombre AND e.fecha_nacimiento = c.fecha_nacimientoORDER BY e.apellido, e.nombre;

call count cpu elapsed disk query current rows--------- ------- ------ ------- ------ ------ -------- ------Parse 1 0 0.12 0 0 0 0Execute 1 0 0.96 0 0 1 0Fetch 11 0 9.82 278 364 370 151--------- ------- ------ ------- ------ ------ -------- ------Total 13 0 10.9 278 364 371 151

Salida del TKPROF:

TASA VALOR RECOMENDADO

VALOR ENCONTRADO

(f+g) / h Entre 10 y 20 4.9 aprox.

d / e 1 (o cerca de 1)

1

i / j > 1 13.73

k / (f+g) Menos de 10%

37.8% aprox