Mostrando las entradas con la etiqueta tuning. Mostrar todas las entradas
Mostrando las entradas con la etiqueta tuning. Mostrar todas las entradas

miércoles, 26 de febrero de 2014

Analizando sentencias con SQL Profile activo en Oracle

Si queremos analizar la performance de una sentencia SQL que tiene un SQL profile habilitado (Oracle 10g o posterior) sin afectar al resto de los usuarios del sistema, ¿cómo hacemos para ver el plan de ejecución original de la sentencia si no se usara el SQL profile?.
Asumiendo que lo vamos a hacer un tiempo después de tener el SQL profile activo y por lo tanto no está presente en la SGA (V$SQL) ni en el repositorio de AWR.

No es necesario deshabilitar ni borrar el SQL profile existente, se puede cambiar el parámetro SQLTUNE_CATEGORY a nivel de sesión para que no se use el SQL profile activo:
SQL> alter session set sqltune_category='OTRA';
Los SQL profile se crean en una categoría (por defecto 'default'), y se usan si la categoría de la sesión (este parámetro) coincide con la del SQL profile creado. Para ver el plan de ejecución original de la sentencia sin usar el SQL profile activo, alcanza con asignar un string cualquiera a la categoría de la sesión actual.

A continuación vemos un ejemplo completo de este comportamiento, incluyendo la creación de un SQL profile sobre una sentencia para forzar el uso de un índice, y luego cambiar este parámetro para ver el plan original, usando Oracle Enterprise Edition 11.2.0.2.

Uso el script coe_xfr_sql_profile.sql provisto por Oracle en el utilitario SQLT (ver nota de soporte 215187.1)  para crear un SQL profile a partir de los hints de una sentencia previamente ejecutada. Esta es la forma más simple de crear un SQL profile para ilustrar con un ejemplo reproducible el cambio de parámetro, aunque el caso queda un tanto artificial. Hay mucha documentación sobre las formas de crear SQL Profiles, pero no es el foco de este post.
De todas formas, este procedimiento es muy útil para troubleshooting de performance, por lo que es interesante tenerlo presente, aunque en este caso solo sea para ilustrar.

Primero creo una tabla, un índice, y ejecuto una consulta que lo usa:
oracle@oraculo:~> sqlplus / as sysdba SQL*Plus: Release 11.2.0.2.0 Production on Mié Feb 26 14:55:15 2014 Copyright (c) 1982, 2010, Oracle. All rights reserved. Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.2.0 - 64bit Production With the Partitioning, Real Application Clusters and Automatic Storage Management options 14:56:08 SQL> alter session set current_schema=PRU; Session altered. 14:56:46 SQL> create table pp(n number, c varchar2(100)); Table created. 14:57:03 SQL> insert into pp select rownum, object_id from dba_objects where rownum < 100; 99 rows created. 14:57:33 SQL> create index pp_idx on pp(n); Index created. 14:57:52 SQL> select * from pp where n=1; N C ---------- --------------------------------------------------------------------------------- 1 28 14:59:17 SQL> select * from table(dbms_xplan.display_cursor); PLAN_TABLE_OUTPUT -------------------------------------------------------------------------------------------- SQL_ID 86svufrd72xqg, child number 0 ------------------------------------- select * from pp where n=1 Plan hash value: 2830885032 -------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 1 (100)| | | 1 | TABLE ACCESS BY INDEX ROWID| PP | 1 | 65 | 1 (0)| 00:00:01 | |* 2 | INDEX RANGE SCAN | PP_IDX | 1 | | 1 (0)| 00:00:01 | -------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 2 - access("N"=1) Note ----- - dynamic sampling used for this statement (level=2) 23 rows selected.
Ya tenemos nuestra tabla PP con un índice sobre la columna N, y la consulta que lo usa.
Ahora creamos otra consulta que hace un full scan sobre la tabla, y es a la que luego vamos a asignarle un SQL profile para que use el índice:
14:59:22 SQL> select /*+ full(pp)*/ * from pp where n=1; N C ---------- ----------------------------------------------------------------------------------- 1 28 14:59:37 SQL> select * from table(dbms_xplan.display_cursor); PLAN_TABLE_OUTPUT ---------------------------------------------------------------------------------------------- SQL_ID btpjqgv0u0stb, child number 0 ------------------------------------- select /*+ full(pp)*/ * from pp where n=1 Plan hash value: 2338859486 -------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 3 (100)| | |* 1 | TABLE ACCESS FULL| PP | 1 | 65 | 3 (0)| 00:00:01 | -------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter("N"=1) Note ----- - dynamic sampling used for this statement (level=2) 22 rows selected. 15:02:10 SQL> col sql_text for a45 15:02:10 SQL> select sql_id, plan_hash_value, executions, sql_text from v$sql where sql_id in ('btpjqgv0u0stb','86svufrd72xqg'); SQL_ID PLAN_HASH_VALUE EXECUTIONS SQL_TEXT ------------- --------------- ---------- --------------------------------------------- btpjqgv0u0stb 2338859486 1 select /*+ full(pp)*/ * from pp where n=1 86svufrd72xqg 2830885032 1 select * from pp where n=1
Vemos los SQL_ID de ambas consultas, junto con el plan de ejecución usado.
Ahora usamos el script coe_xfr_sql_profile.sql para crear un SQL profile a la consulta lenta (btpjqgv0u0stb) y que use el plan de la otra (2830885032). Estos son los parámetros que se le deben ingresar al script:
SQL> sta coe_xfr_sql_profile.sql Parameter 1: SQL_ID (required) Enter value for 1: btpjqgv0u0stb PLAN_HASH_VALUE AVG_ET_SECS --------------- ----------- 2338859486 ,004 Parameter 2: PLAN_HASH_VALUE (required) Enter value for 2: 2830885032 Values passed to coe_xfr_sql_profile: ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ SQL_ID : "btpjqgv0u0stb" PLAN_HASH_VALUE: "2830885032" SQL>BEGIN 2 IF :sql_text IS NULL THEN 3 RAISE_APPLICATION_ERROR(-20100, 'SQL_TEXT for SQL_ID &&sql_id. was not found in memory (gv$sqltext_with_newlines) or AWR (dba_hist_sqltext).'); 4 END IF; 5 END; 6 / SQL>SET TERM OFF; SQL>BEGIN 2 IF :other_xml IS NULL THEN 3 RAISE_APPLICATION_ERROR(-20101, 'PLAN for SQL_ID &&sql_id. and PHV &&plan_hash_value. was not found in memory (gv$sql_plan) or AWR (dba_hist_sql_plan).'); 4 END IF; 5 END; 6 / SQL>SET TERM OFF; Execute coe_xfr_sql_profile_btpjqgv0u0stb_2830885032.sql on TARGET system in order to create a custom SQL Profile with plan 2830885032 linked to adjusted sql_text. COE_XFR_SQL_PROFILE completed.
Vemos que se ejecutó de forma exitosa, así que nos generó un script que crea el SQL profile.
Lo ejecutamos:
SQL> sta coe_xfr_sql_profile_btpjqgv0u0stb_2830885032.sql SQL> REM SQL> REM $Header: 215187.1 coe_xfr_sql_profile_btpjqgv0u0stb_2830885032.sql 11.4.4.4 2014/02/26 carlos.sierra $ SQL> REM SQL> REM Copyright (c) 2000-2012, Oracle Corporation. All rights reserved. SQL> REM SQL> REM AUTHOR SQL> REM carlos.sierra@oracle.com SQL> REM SQL> REM SCRIPT SQL> REM coe_xfr_sql_profile_btpjqgv0u0stb_2830885032.sql SQL> REM SQL> REM DESCRIPTION SQL> REM This script is generated by coe_xfr_sql_profile.sql SQL> REM It contains the SQL*Plus commands to create a custom SQL> REM SQL Profile for SQL_ID btpjqgv0u0stb based on plan hash SQL> REM value 2830885032. SQL> REM The custom SQL Profile to be created by this script SQL> REM will affect plans for SQL commands with signature SQL> REM matching the one for SQL Text below. SQL> REM Review SQL Text and adjust accordingly. SQL> REM SQL> REM PARAMETERS SQL> REM None. SQL> REM SQL> REM EXAMPLE SQL> REM SQL> START coe_xfr_sql_profile_btpjqgv0u0stb_2830885032.sql; SQL> REM SQL> REM NOTES SQL> REM 1. Should be run as SYSTEM or SYSDBA. SQL> REM 2. User must have CREATE ANY SQL PROFILE privilege. SQL> REM 3. SOURCE and TARGET systems can be the same or similar. SQL> REM 4. To drop this custom SQL Profile after it has been created: SQL> REM EXEC DBMS_SQLTUNE.DROP_SQL_PROFILE('coe_btpjqgv0u0stb_2830885032'); SQL> REM 5. Be aware that using DBMS_SQLTUNE requires a license SQL> REM for the Oracle Tuning Pack. SQL> REM 6. If you modified a SQL putting Hints in order to produce a desired SQL> REM Plan, you can remove the artifical Hints from SQL Text pieces below. SQL> REM By doing so you can create a custom SQL Profile for the original SQL> REM SQL but with the Plan captured from the modified SQL (with Hints). SQL> REM SQL> WHENEVER SQLERROR EXIT SQL.SQLCODE; SQL> REM SQL> VAR signature NUMBER; SQL> VAR signaturef NUMBER; SQL> REM SQL> DECLARE 2 sql_txt CLOB; 3 h SYS.SQLPROF_ATTR; 4 PROCEDURE wa (p_line IN VARCHAR2) IS 5 BEGIN 6 DBMS_LOB.WRITEAPPEND(sql_txt, LENGTH(p_line), p_line); 7 END wa; 8 BEGIN 9 DBMS_LOB.CREATETEMPORARY(sql_txt, TRUE); 10 DBMS_LOB.OPEN(sql_txt, DBMS_LOB.LOB_READWRITE); 11 -- SQL Text pieces below do not have to be of same length. 12 -- So if you edit SQL Text (i.e. removing temporary Hints), 13 -- there is no need to edit or re-align unmodified pieces. 14 wa(q'[select /*+ full(pp)*/ * from pp where n=1]'); 15 DBMS_LOB.CLOSE(sql_txt); 16 h := SYS.SQLPROF_ATTR( 17 q'[BEGIN_OUTLINE_DATA]', 18 q'[IGNORE_OPTIM_EMBEDDED_HINTS]', 19 q'[OPTIMIZER_FEATURES_ENABLE('11.2.0.2')]', 20 q'[DB_VERSION('11.2.0.2')]', 21 q'[OPT_PARAM('optimizer_index_cost_adj' 1)]', 22 q'[OPT_PARAM('optimizer_index_caching' 100)]', 23 q'[ALL_ROWS]', 24 q'[OUTLINE_LEAF(@"SEL$1")]', 25 q'[INDEX_RS_ASC(@"SEL$1" "PP"@"SEL$1" ("PP"."N"))]', 26 q'[END_OUTLINE_DATA]'); 27 :signature := DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE(sql_txt); 28 :signaturef := DBMS_SQLTUNE.SQLTEXT_TO_SIGNATURE(sql_txt, TRUE); 29 DBMS_SQLTUNE.IMPORT_SQL_PROFILE ( 30 sql_text => sql_txt, 31 profile => h, 32 name => 'coe_btpjqgv0u0stb_2830885032', 33 description => 'coe btpjqgv0u0stb 2830885032 '||:signature||' '||:signaturef||'', 34 category => 'DEFAULT', 35 validate => TRUE, 36 replace => TRUE, 37 force_match => FALSE /* TRUE:FORCE (match even when different literals in SQL). FALSE:EXACT (similar to CURSOR_SHARING) */ ); 38 DBMS_LOB.FREETEMPORARY(sql_txt); 39 END; 40 / PL/SQL procedure successfully completed. SQL> WHENEVER SQLERROR CONTINUE SQL> SET ECHO OFF; SIGNATURE --------------------- 613978514929328923 SIGNATUREF --------------------- 16370312570377067161 ... manual custom SQL Profile has been created COE_XFR_SQL_PROFILE_btpjqgv0u0stb_2830885032 completed
El SQL profile se creó, así que validamos si la consulta que antes hacía un acceso full sobre la tabla ahora toma el índice:
15:14:08 SQL> select /*+ full(pp)*/ * from pp where n=1; N C ---------- --------------------------------------------------------------------- 1 28 15:14:09 SQL> select * from table(dbms_xplan.display_cursor); PLAN_TABLE_OUTPUT --------------------------------------------------------------------------------------------- SQL_ID btpjqgv0u0stb, child number 1 ------------------------------------- select /*+ full(pp)*/ * from pp where n=1 Plan hash value: 2830885032 -------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 1 (100)| | | 1 | TABLE ACCESS BY INDEX ROWID| PP | 1 | 65 | 1 (0)| 00:00:01 | |* 2 | INDEX RANGE SCAN | PP_IDX | 1 | | 1 (0)| 00:00:01 | -------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 2 - access("N"=1) Note ----- - SQL profile coe_btpjqgv0u0stb_2830885032 used for this statement 23 rows selected. 15:14:50 SQL> select category, status 15:15:04 2 from dba_sql_profiles 15:15:09 3 where name='coe_btpjqgv0u0stb_2830885032'; CATEGORY STATUS ------------------------------ -------- DEFAULT ENABLED
Perfecto, el SQL profile está haciendo lo que esperamos y está activo.
Recién ahora estamos en la situación que me interesaba mostrar: ¿cómo hacemos para ver el plan de ejecución original de esta sentencia?. Uso el string OTRA, pero podría ser cualquier string distinto de DEFAULT:
15:15:50 SQL> alter session set sqltune_category='OTRA'; Session altered. 15:16:02 SQL> select /*+ full(pp)*/ * from pp where n=1; N C ---------- --------------------------------------------------------------------------------- 1 28 15:16:12 SQL> select * from table(dbms_xplan.display_cursor); PLAN_TABLE_OUTPUT -------------------------------------------------------------------------------------------- SQL_ID btpjqgv0u0stb, child number 2 ------------------------------------- select /*+ full(pp)*/ * from pp where n=1 Plan hash value: 2338859486 -------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | | | 3 (100)| | |* 1 | TABLE ACCESS FULL| PP | 1 | 65 | 3 (0)| 00:00:01 | -------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 1 - filter("N"=1) Note ----- - dynamic sampling used for this statement (level=2) 22 rows selected.
Vemos que al ejecutar la sentencia se vuelve a comportar como antes, sin usar el SQL profile.

Espero les sea útil.

lunes, 23 de septiembre de 2013

Histogramas de tiempos de ejecución SQL con AWK

Hace unos días tuve que analizar la performance de una aplicación java que usa Oracle y evaluar si el problema de lentitud estaba en las sentencias SQL ejecutadas. El escenario es:
 - el código no se puede modificar
 - la base de datos usada recibe cientos de sentencias por segundo de varias aplicaciones que vienen del mismo servidor.
 - en el mismo servidor de aplicaciones se ejecutan varias aplicaciones java similares a la que tiene problemas.

Como el problema es en producción, no había posibilidad de bajar el resto de las aplicaciones para dejar solo el tráfico de la problemática.

Así que la alternativa disponible fue habilitar un log de ejecución de sentencias en la aplicación.
Esto genera una entrada por cada ejecución en el archivo con este formato:
2013-09-09 14:38:44,066 [org.hibernate.SQL] Sentencia

No sabemos en qué momento se escribe la entrada en el log. Puede ser antes o después de ejecutar la sentencia. Pero lo que sí sabemos es que el tiempo de ejecución es como máximo el tiempo entre dos entradas consecutivas. Así que como una aproximación sirve para tener una idea de por donde puede venir el problema.

Obtener datos útiles de archivos de log con sentencias SQL es una alternativa muy conocida y bien aprovechada en MySQL con utilitarios como pt-query-digest. Sin intentar imitarlo, me alcanza con ver los tiempos de ejecución de las sentencias, cosa que se puede obtener con un simple script AWK tomando el tiempo transcurrido entre dos entradas consecutivas. Por ejemplo, para ver las que demoraron más de un segundo:
oracle@oraculo:~> awk '{split($3,a,":"); sec=60*(60*a[1]+a[2])+a[3]; if(b!=0 && (sec-b)>1){ print $3 " - " sec - b; }; b=sec}' /tmp/pp.txt
    14:38:49,899 - 5,015
    14:38:51,995 - 2,094
    14:43:46,037 - 2,067
    14:43:51,054 - 5,015
    14:43:56,072 - 5,015

Así puedo ir al log y ver cuales fueron esas sentencias para después analizar si realmente tienen buenos planes de ejecución.

Limpié del archivo entradas iniciales antes de empezar la ejecución de sentencias, y algunas entradas finales, mirando con un editor los números de línea (vi y g es lo más simple). Así nos quedamos con las líneas 6821 a 74572:

oracle@oraculo:~> head -n 74572 myjavaapp.2013091112.log | tail -n +6821 > /tmp/pp.txt

Las sentencias SQL incluidas en este log son:
oracle@oraculo:~> grep -ic insert /tmp/pp.txt
    507
oracle@oraculo:~> grep -ic delete /tmp/pp.txt
    0
oracle@oraculo:~> grep -ic update /tmp/pp.txt
    524
oracle@oraculo:~> grep -ic select /tmp/pp.txt
    2254

Para tener una visión más clara del tiempo de ejecución de las sentencias, armo histogramas de tiempos de ejecución, redondeando a 0,1 segundo (tiempos más chicos no me interesa optimizar). El formato de esta salida es: tiempo de ejecución en segundos y cantidad de sentencias.
oracle@oraculo:~> awk 'BEGIN {b=0;} { split($3,a,":"); sec=60*(60*a[1]+a[2])+a[3]; if(b!=0){ n[int((sec-b)*10+.5)/10]++}; b=sec} END {for (i in n) print i,n[i]}' /tmp/pp2.txt | sort -n
   
    0 2268
    0,1 161
    0,2 421
    0,3 207
    0,4 90
    0,5 68
    0,6 50
    0,7 11
    0,8 1
    0,9 2
    2,1 2
    5 3

Se puede ver con claridad que la mayoría de las sentencias se resuelven en menos de 0,4 segundos, lo que indica con claridad que la base de datos no está teniendo problemas, y se debe analizar el código de la aplicación en busca de más pistas de la lentitud observada.


Espero les sea útil.
Un saludo.

sábado, 13 de marzo de 2010

Usando funciones en índices para columnas con valores dispersos

Hace unos días tuve que mejorar una consulta como esta que demoraba varios minutos y generó una tranca en el acceso a disco, con el evento 'db file scattered read':

select *
from SMALL
where DESTINO2 = 2 and solicitud2 not in
(select solicitud from TINY
where DESTINO=2 and solicitud not in
(select solicitud2 from BIGTABLE where estado='F'));

El plan de ejecución es:

--------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
--------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2833 | 376K| 220K (2)| 00:44:08 |
|* 1 | FILTER | | | | | |
|* 2 | TABLE ACCESS FULL | SMALL | 2833 | 376K| 173 (1)| 00:00:03 |
|* 3 | FILTER | | | | | |
|* 4 | TABLE ACCESS FULL| TINY | 1 | 8 | 122 (2)| 00:00:02 |
|* 5 | TABLE ACCESS FULL| BIGTABLE | 1 | 5 | 34 (3)| 00:00:01 |
--------------------------------------------------------------------------------------------

El primer paso obvio es crear índices, ya que estas tablas solo tienen PK y no son estas columnas. Revisando el tamaño de las tablas, hay una muy grande:

TABLE_NAME NUM_ROWS
------------------------------ ----------
SMALL 51602
BIGTABLE 10762233
TINY 26882

Sobre las dos tablas chicas se pueden crear sin problemas los indices faltantes, pero sobre la grande conviene analizar un poco más:

create index i_TINY on TINY (DESTINO, solicitud);
create index i_SMALL on SMALL (DESTINO2, solicitud2);

En BIGTABLE revisamos la distribución de datos en la columna usada para filtrar, para ver que tan selectivo es el filtro usado por la consulta:

select estado, count(1)
from BIGTABLE
group by estado;

E COUNT(1)
- ----------
H 13154
P 10321688
D 1740
A 288
E 13349
L 2659
S 1829
G 4831
F 2552

En este caso, para el valor F hay muy pocos registros. Habría que revisar el código de la aplicación para ver si este filtro es estático.

En caso que pueda usarse cualquier valor para filtrar, hay que evaluar la frecuencia de sentencias DML (insert/update/delete) sobre la tabla, ya que un nuevo índice puede hacer que estas operaciones sean más lentas, y además se debe evaluar el espacio que ocupa el mismo.

En caso que siempre se filtre por F es donde se pone interesante, ya que podemos indexar usando una función de forma que el índice incluya sólo los registros que nos interesa. Esto hace que el índice sea mucho más chico, por lo tanto ocupa muy poco espacio, involucra menos operaciones de IO, y no enlentece tanto las operaciones DML.
Solo debe hacerse un pequeño cambio en la forma de escribir la consulta para que sea usado por Oracle.

El índice quedaría:

create index i_BIGTABLE_est on BIGTABLE(decode(estado,'F','F',null),solicitud2);

Y la nueva consulta :

select *
from SMALL
where DESTINO2 = 2 and solicitud2 not in
(select solicitud from TINY
where DESTINO=2 and solicitud not in
(select solicitud2 from BIGTABLE where decode(estado,'F','F',null)='F'));

El plan ahora es mucho más lindo, y lo que es mejor, involucra mucho menos operaciones de IO, al utilizar índices que son mucho más chicos que la tabla original:

-----------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-----------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 2833 | 376K| 35522 (4)| 00:07:07 |
|* 1 | FILTER | | | | | |
|* 2 | TABLE ACCESS FULL | SMALL | 2833 | 376K| 173 (1)| 00:00:03 |
|* 3 | FILTER | | | | | |
|* 4 | INDEX FAST FULL SCAN| I_TINY | 1 | 8 | 22 (5)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | I_BIGTABLE_EST | 1 | 5 | 3 (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------