viernes, 15 de agosto de 2008

Query para ver lo que está sucediendo

Recientemente Tanel Poder en su blog publicó esta entrada. Vale mucho la pena el enfoque qué él le da.

Generalmente cuando me toca ir con algún cliente por algún tema de performance, siempre suele haber dos situaciones distintas:


1) Están por correr procesos pesados y se quiere una foto de todo lo que está sucediendo en el sistema.

2) El sistema da la apariencia de estar pasmado.

Para el primer caso, lo que puedo sugerir es la activación de statspack



SQL> @?/rdbms/admin/spcreate.sql

Creating Package STATSPACK...

Paquete creado.

No hay errores.
Creating Package Body STATSPACK...

Cuerpo del paquete creado.

No hay errores.

NOTE:
SPCPKG complete. Please check spcpkg.lis for any errors.

SQL> conn perfstat
Introduzca la contraseña:
Conectado.

SQL> exec statspack.snap(I_SNAP_LEVEL=>7);


A partir de este punto, dejo que corran todo lo que deben de correr, y después de unos 15 mins, o que los procesos han terminado, vuelvo a ejecutar


SQL> exec statspack.snap(I_SNAP_LEVEL=>7);


Genero los reportes diferenciales, y analizo la información



SQL> define begin_snap=1;
SQL> define end_snap=2;
SQL> @?/rdbms/admin/spreport.sql


Hay que recordar que toda la información es generalizada y agregada es decir, supongamos que tenemos lo siguiente:


Top 5 Timed Events
~~~~~~~~~~~~~~~~~~
Event Waits Time (s)
----------------------------------------- ------------ -----------
CPU time 15,000
db file scattered read 21,156 830
control file sequential read 1,261 10
....


Y esto en un periodo de 1 Hora entre snapshots, debemos de tomar en cuenta que la información es agregada.

En este ejemplo (totalmente ficticio), pareciera que la instancia tiene problemas de CPU, pero si pensáramos que el equipo cuenta con 32 procesadores, estaríamos viendo que en promedio cada CPU se ocupó 13.5% y el problema podría venir por otro lado.


Para las situaciones en donde el sistema aparenta estar pasmado, o se quiere saber lo que está sucediendo, suelo tener 3 sentencias SQL (la primera muy similar a la de Tanel)


SQL> select count(1), event
2 from v$session_wait
3 group by event
4 order by 1 desc;

COUNT(1) EVENT
---------- -------------------------------------
19 enq: TM - contention
12 rdbms ipc message
1 jobq slave wait
1 SQL*Net message to client
1 smon timer
1 pmon timer
1 SQL*Net message from client

7 filas seleccionadas.


Esto nos dice que hay 19 sesiones sufriendo de encolamiento (pero lo mismo puede aplicar para cualquier wait != Idle)


SQL> select count(1), s.sql_hash_value, sw.event
2 from v$session s, v$session_wait sw
3 where s.sid=sw.sid
4 group by s.sql_hash_value,sw.event
5 order by 1 desc;

COUNT(1) SQL_HASH_VALUE EVENT
---------- -------------- ----------------------------
19 3864513861 enq: TM - contention
11 0 rdbms ipc message
1 2390948774 SQL*Net message to client
1 0 smon timer
1 3393152264 rdbms ipc message
1 0 pmon timer
1 0 jobq slave wait
1 0 SQL*Net message from client

8 filas seleccionadas.

Y finalmente, podemos ir al Shared pool a ver el plan de ejecución


SQL> select * from table(dbms_xplan.display_cursor(3864513861));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------

HASH_VALUE 3864513861, child number 0
--------------------------------------
lock table hilos in exclusive mode

Plan hash value: 2876205575

-----------------------------------
| Id | Operation | Name |
-----------------------------------
| 0 | DDL STATEMENT | |
| 1 | TABLE ACCESS FULL| HILOS |
-----------------------------------


El último query sólo se puede hacer en instancias 10g+, en caso de nueve, se deberá buscar el plan de ejecución en V$SQL_PLAN.

Si se está usando 10g, tambien se puede evitar el acceso a la vista v$session_wait, ya que v$session contiene la información de eventos de espera.


SQL> select count(1) ,sql_hash_value, event
2 from v$session
3 group by sql_hash_value, event
4 order by 1 desc;

COUNT(1) SQL_HASH_VALUE EVENT
---------- -------------- -----------------------------
19 3864513861 enq: TM - contention
11 0 rdbms ipc message
1 0 SQL*Net message from client
1 0 smon timer
1 0 pmon timer
1 2593210877 SQL*Net message to client
1 0 jobq slave wait
1 3393152264 rdbms ipc message

8 filas seleccionadas.