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.