Friday, February 18, 2011

What is a session doing in DB?

Please help to check my session!!! Maybe, We often hear this question. If we have EM, this is easy to check and investigate.
But... If we can only use sql command, what is your idea or step?
However, someone asked me this question and only knew username, what I should start to check? I...
checked blocking (Link): *** 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='DEMO';

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('ckg31y8rg6psa','','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
How about your idea? wish to know...

2 comments:

Charles Hooper said...

Surachart,

The session is either on the CPU (thus Oracle is showing the last wait event) or is performing serial direct path reads while reading the table blocks from disk rather than using what was the typical method of performing full table scans using db file scattered read waits (check V$SESSION_WAIT is see if the session is still on the CPU). Since the 10046 trace file showed that wait events were still being written to the trace file, that very likely indicates that the session was actively waiting on the wait event, and not on the CPU when you queried V$SESSION.

Serial direct path reads were introduced in Oracle 11g. You can find several good articles by searching for the following keywords:
serial direct path read oracle

Surachart said...

Thank you -)
@Charles Hooper