Wednesday, April 26, 2017

Track session activity in DB

What is a session doing in DB?


*** this sql can not use on version < 10G ***
select 'Session ID=' ||SID ||'(Inst '||INST_ID||') IS BLOCKED BY Session ID='|| BLOCKING_SESSION || '(Inst '||BLOCKING_INSTANCE||')' from gv$session where BLOCKING_SESSION is not null;
... OK!!! no blocking, time to use username to find out more about that session, investigation and answer user -)
SQL> select sid, serial#, username, program, event, p1, status, sql_id from v$session where username='APPS';

SID SERIAL# USERNAME PROGRAM EVENT P1 STATUS SQL_ID
---------- ---------- -------- ----------------------------------- ------------------------------ -- -------- -------------
45 43 DEMO sqlplus@linuxclient (TNS V1-V3) direct path read 4 ACTIVE ckg31y8rg6psa
That showed SID, EVENT, STATUS and SQL_ID, then checked about SQL statement.
SQL> select sql_text, disk_reads, buffer_gets, cpu_time from v$sqlstats where sql_id='ckg31y8rg6psa';

SQL_TEXT DISK_READS BUFFER_GETS CPU_TIME
---------------------------------------------------------------------- ---------- ----------- ----------
select id, sum (id + 10000)/1 from tb_test where id >1000 group by id 23530 23312 95802415
Checked Xplan:
SQL> select * from table(dbms_xplan.display_cursor('f9zzgqzd1gdwg','','typical'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------
SQL_ID ckg31y8rg6psa, child number 0
-------------------------------------
select id, sum (id + 10000)/1 from tb_test where id >1000 group by id

Plan hash value: 2744048799
------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 856 (100)| |
| 1 | HASH GROUP BY | | 1179K| 14M| 856 (7)| 00:00:11 |
|* 2 | TABLE ACCESS FULL| TB_TEST | 1179K| 14M| 811 (2)| 00:00:10 |
------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
2 - filter("ID">1000)
Enabled trace on that session:
SQL> exec dbms_monitor.session_trace_enable(45,43);

PL/SQL procedure successfully completed.

SQL> select sql_trace from v$session where sid=45 and serial# =43;

SQL_TRACE
--------
ENABLED

SQL> select p.spid, p.tracefile from v$session s, v$process p where s.paddr = p.addr and s.sid=45;

SPID TRACEFILE
------------------------ -------------------------------------------------------
970 /oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_970.trc
Checked from trace file, what that session was doing.
$ tail -f /oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_970.trc
WAIT #5417428: nam='direct path read' ela= 120 file number=4 first dba=617 block cnt=15 obj#=81188 tim=1298022456269076
Or used "tkprof" to make trace report file.
$ tkprof /oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_970.trc out.prf sys=no
Example:
SQL ID: ckg31y8rg6psa Plan Hash: 2744048799

select id, sum (id + 10000)/1
from
tb_test where id >1000 group by id

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.05 0.07 398 80 0 0
Execute 2 0.00 0.00 0 0 0 0
Fetch 68875 25.20 26.06 5384 5709 0 1033097
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 68879 25.25 26.13 5782 5789 0 1033097
What is the answer? - that session was waiting at 'direct path read' event on file_id=4:
SQL> select tablespace_name from dba_data_files where file_id=4;

TABLESPACE_NAME
------------------------------
USERS
and SQL in that session was doing "TABLE ACCESS FULL" and fetched many rows.

then disabled trace on that session:
SQL> exec dbms_monitor.session_trace_disable(45,43);

PL/SQL procedure successfully completed.

SQL> select sql_trace from v$session where sid=45 and serial# =43;

SQL_TRACE
--------
DISABLED

No comments:

Post a Comment