sábado, 8 de septiembre de 2007

Monitoreando el progreso de largas ejecuciones

Para monitorear las largas ejecuciones que se producen en la base de datos, contamos con la vista del diccionario de datos llamada V$SESSION_LONGOPS. Esta vista nos permite monitorear tanto las sentencias DML como así también las sentencias DDL.
Pero cuáles son las sentencias que aparecen en esa vista?
Una ejecución es considerada una operación 'larga' y aparece en la vista V$SESSION_LONGOPS si la ejecución demora más de 6 segundos. Este no es el único criterio por el cual una sentencia aparece en la vista. También aparecen las operaciones en la vista si Oracle tiene que leer más de 10.000 bloques de la tabla.
Pero no todas las operaciones que cumplen estos criterios aparecen en esa vista.

Cada versión de Oracle agrega más tipos de operaciones a la vista V$SESSION_LONGOPS.
Algunas de esas operaciones son:
- Table Scan
- Index Fast Full Scan
- Hash Join
- Sort/Merge
- Sort Output
- Estadísticas
- Rollback

Veamos un ejemplo:

SQL_9iR2> CREATE TABLE test AS
2 SELECT level a, level b, level c
3 FROM dual
4 CONNECT BY level <= 1000000 ;

Table created.

SQL_9iR2> EXEC dbms_stats.GATHER_TABLE_STATS(USER,'TEST') ;

PL/SQL procedure successfully completed.

Bien, ya tenemos nuestra tabla creada, cargada con 1 millón de registros y analizada.
Lo que vamos a hacer ahora es ejecutar una consulta en una sesión, y en otra sesión vamos a consultar a la vista V$SESSION_LONGOPS mientras la consulta se ejecuta.

En la SESION_1 ejecuto la consulta (Esta consulta realiza un Full Scan sobre la tabla):

SQL_9iR2> SELECT a, b, c
2 FROM test
3 ORDER BY a ASC, b DESC, c ASC ;

En la SESION_2 ejecuto la consulta sobre la vista:

SQL_9iR2> SELECT sid, serial#, username, opname, sql_hash_value hash_value,
2 TO_CHAR(start_time,'HH24:MI:SS') "INICIO",
3 (sofar/totalwork)*100 "%"
4 FROM v$session_longops
5 WHERE (sofar/totalwork)*100 < 100 ;

no rows selected

Fijense, que mientras estoy corriendo la consulta de la SESION_1, cuando ejecuto la consulta de la SESION_2, no me devuelve ningún registro. Esto sucede porque aún Oracle no leyó 10.000 bloques de datos.
Qué sucede si intento ejecutar la consulta nuevamente?

SQL_9iR2> SELECT sid, serial#, username, opname, sql_hash_value hash_value,
2 TO_CHAR(start_time,'HH24:MI:SS') "INICIO",
3 (sofar/totalwork)*100 "%"
4 FROM v$session_longops
5 WHERE (sofar/totalwork)*100 < 100 ;

SID SERIAL# USERNAME OPNAME HASH_VALUE INICIO %
---------- ---------- ---------- --------------- ---------- -------- ----------
87 6852 LEO Sort Output 3570479103 22:27:58 4.24448217

1 row selected.

Vemos que el porcentaje está en 4.24 y tenemos que llegar al 100 porciento para que la consulta termine de ejecutarse.
Ejecuto nuevamente la consulta:

SQL_9iR2> SELECT sid, serial#, username, opname, sql_hash_value hash_value,
2 TO_CHAR(start_time,'HH24:MI:SS') "INICIO",
3 (sofar/totalwork)*100 "%"
4 FROM v$session_longops
5 WHERE (sofar/totalwork)*100 < 100 ;

SID SERIAL# USERNAME OPNAME HASH_VALUE INICIO %
---------- ---------- ---------- --------------- ---------- -------- ----------
87 6852 LEO Sort Output 3570479103 22:27:58 7.53820034

1 row selected.

El porcentaje se incrementó. Ahora se encuentra en 7.5 y aún falta mucho para que la consulta de la SESION_1 termine de ejecutarse.

Algo interesante para ver de la vista, es que tenemos una columna llamada SQL_HASH_VALUE en donde nos muestra el valor hash (recordemos que cuando Oracle tiene que buscar una consulta en la Shared Pool, busca esa consulta mediante un valor hash. Cuando ejecutamos una consulta, Oracle aplica una función sobre la consulta obteniendo el valor hash que vemos en ésta tabla en la columna HASH_VALUE) de la consulta que estamos ejecutando. Si tomamos ese valor y buscamos la consulta en la V$SQLTEXT...

SQL_9iR2> SELECT sql_text
2 FROM v$sqltext
3 WHERE hash_value = 3570479103
4 ORDER BY piece ;

SQL_TEXT
------------------------------------------------------------
SELECT a, b, c FROM test ORDER BY a ASC, b DESC, c ASC

1 row selected.

Bien, ahora veamos lo siguiente. El paquete DBMS_APPLICATION_INFO, contiene un procedimiento llamado SET_SESSION_LONGOPS, que se utiliza para popular la vista V$SESSION_LONGOPS desde una aplicación.

Veamos un ejemplo:

SQL_9iR2> DECLARE
2 l_rindex BINARY_INTEGER := DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS_NOHINT ;
3 l_sofar NUMBER := 0 ;
4 l_slno BINARY_INTEGER ;
5 BEGIN
6 FOR i IN ( SELECT a, b, c
7 FROM test
8 WHERE rownum <= 1000
9 ORDER BY a ASC, b DESC, c ASC ) LOOP
10
11 l_sofar := l_sofar + 1 ;
12
13 DBMS_APPLICATION_INFO.SET_SESSION_LONGOPS
14 (rindex => l_rindex ,
15 slno => l_slno ,
16 op_name => 'TEST LEO' ,
17 target => NULL ,
18 context => 0 ,
19 sofar => l_sofar ,
20 totalwork => 1000 ,
21 target_desc => 'Completado') ;
22
23 END LOOP ;
24 END ;
25 /

PL/SQL procedure successfully completed.

Ese bloque PL/SQL anónimo, iteró 1000 veces y logueo la operación en la vista.
Si ahora queremos ver esa información, lo único que tenemos que hacer es consultar la V$SESSION_LONGOPS.

SQL_9iR2> SELECT sid, serial#, username, opname, sql_hash_value hash_value,
2 TO_CHAR(start_time,'HH24:MI:SS') "INICIO",
3 (sofar/totalwork)*100 "%"
4 FROM v$session_longops ;

SID SERIAL# USERNAME OPNAME HASH_VALUE INICIO %
---------- ---------- ---------- --------------- ---------- -------- ----------
58 19110 LEO TEST LEO 2061745150 23:13:00 100

Como pueden ver, este procedimiento es muy útil cuando queremos, por ejemplo, monitorear una consulta larga y poder identificarla en la vista de manera fácil como en éste último ejemplo.

6 comentarios:

Anónimo dijo...

Excelente muchas gracias.. no desanimes a seguir aportando tu conocimientos

Carlos dijo...

Explica esto:

Introduzca un valor para sid: 141
antiguo 13: where sid=&sid
nuevo 13: where sid=141

SID SERIAL# OPNAME TOTALWORK SOFAR UNITS
---------- ---------- ---------------------------------------------------------------- ---------- ---------- ------
141 13 Table Scan 725262 725262 Blocks
141 13 Sort/Merge 490750 490750 Blocks
141 13 Sort Output 486783 486783 Blocks
141 13 Sort/Merge 518704 1285232 Blocks


Saludos.

Carlos.

chijar dijo...

Leo,
navegando encontre tu blog y me parece muy bueno, es mas, esta en español que es nuestra lengua madre.
Esta muy bueno tu articulo, pero me gustaria preguntarte algo acerca de el.
Hace unos dias tenia un cursor, de un analista que realizaba varios selects e inserts y aun realizando el query para el monitoreo de largas ejecuciones, este no mostraba resultado alguno. Dime, necesariamente tiene que leer 10000 bloques de datos para que recien aparezca?
Basta con que uno de los criterios (6 seg o 10000 bloques) haya sido sobrepasado para que este aparezca como resultado en el query?

Gracias por tu respuesta.
Saludos desde Peru. cesar.

Leonardo Horikian dijo...

Cesar,

Generalmente, si estas ejecutando, por ejemplo, un Insert o Select que demora mucho tiempo en procesar, ésta sentencia va a aparecer en la V$SESSION_LONGOPS. Si no aparece allí, seguramente no cumple alguna de las condiciones que detallo en el artículo.

Saludos.

Yuli dijo...

Estaba buscando info sobre este paquete del sys y no encontraba nada bueno hasta hallar tu blogger
esta muy buena y como dicen en español me facilito mas, gracias

Anónimo dijo...

Me parece muy util, lo posteado.

Gracias por compartirlo.