Thursday, April 16, 2015

Monitor Session Activity Using Trace File (using tkprof)

Trace file are used to trace session/instance level activity. It is also called diagnostic file which are created by the server process. Now I am used DBMS_MONITOR to trace session level activity.

=============================================

C:\Users\rajib.pradhan>sqlplus /nolog

SQL*Plus: Release 11.2.0.1.0 Production on Thu Apr 16 15:47:31 2015

Copyright (c) 1982, 2010, Oracle.  All rights reserved.

SQL> conn HR/HR@192.168.56.100:1521/ORCLN1
Connected.
SQL> select SYS_CONTEXT('USERENV','SID') from dual;

SYS_CONTEXT('USERENV','SID')
--------------------------------------------------------------------------------
57

=============================================

[oracle@OEL64BN1 oracle]$ sqlplus /nolog

SQL*Plus: Release 11.2.0.3.0 Production on Thu Apr 16 15:47:09 2015

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

SQL> conn /as sysdba
Connected.
SQL> SELECT S.SID,S.SERIAL#, P.TRACEFILE
FROM V$SESSION S, V$PROCESS P
WHERE  S.PADDR = P.ADDR
AND S.SID = 57;  2    3    4

       SID    SERIAL#
---------- ----------
TRACEFILE
--------------------------------------------------------------------------------
        57       7889
/u01/app/oracle/diag/rdbms/orcln1/orcln1/trace/orcln1_ora_20927.trc


SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(57,7889,true,true);

PL/SQL procedure successfully completed.
=============================================
SQL> SELECT LAST_NAME, SALARY, DEPARTMENT_NAME
  2  FROM EMPLOYEES E, DEPARTMENTS D
  3  WHERE E.DEPARTMENT_ID=D.DEPARTMENT_ID;

LAST_NAME                     SALARY DEPARTMENT_NAME
------------------------- ---------- ------------------------------
Whalen                          4400 Administration
Hartstein                      13000 Marketing
Fay                             6000 Marketing
Raphaely                       11000 Purchasing
Colmenares                      2500 Purchasing
Khoo                            3100 Purchasing
Baida                           2900 Purchasing
Tobias                          2800 Purchasing

106 rows selected.

SQL>

=============================================

SQL> EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(57,7889);

PL/SQL procedure successfully completed.

SQL> exit
Disconnected from Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
[oracle@OEL64BN1 oracle]$ tkprof /u01/app/oracle/diag/rdbms/orcln1/orcln1/trace/orcln1_ora_20927.trc /u01/app/oracle/trace_output.txt

TKPROF: Release 11.2.0.3.0 - Development on Thu Apr 16 15:49:17 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@OEL64BN1 oracle]$
[oracle@OEL64BN1 oracle]$ cat trace_output.txt

TKPROF: Release 11.2.0.3.0 - Development on Thu Apr 16 15:49:17 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: /u01/app/oracle/diag/rdbms/orcln1/orcln1/trace/orcln1_ora_20927.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SELECT LAST_NAME, SALARY, DEPARTMENT_NAME
FROM EMPLOYEES E, DEPARTMENTS D
WHERE E.DEPARTMENT_ID=D.DEPARTMENT_ID

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         18          0         106
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       11      0.00       0.00          0         18          0         106

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 84
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       106        106        106  MERGE JOIN  (cr=18 pr=0 pw=0 time=663 us cost=6 size=3286 card=106)
        27         27         27   TABLE ACCESS BY INDEX ROWID DEPARTMENTS (cr=12 pr=0 pw=0 time=702 us cost=2 size=432 card=27)
        27         27         27    INDEX FULL SCAN DEPT_ID_PK (cr=6 pr=0 pw=0 time=404 us cost=1 size=0 card=27)(object id 76362)
       106        106        106   SORT JOIN (cr=6 pr=0 pw=0 time=1087 us cost=4 size=1605 card=107)
       107        107        107    TABLE ACCESS FULL EMPLOYEES (cr=6 pr=0 pw=0 time=106 us cost=3 size=1605 card=107)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       9        0.00          0.00
  SQL*Net message from client                     8        0.06          0.34



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        9      0.00       0.00          0         18          0         106
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       11      0.00       0.00          0         18          0         106

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       9        0.00          0.00
  SQL*Net message from client                     8        0.06          0.34


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

    1  user  SQL statements in session.
    0  internal SQL statements in session.
    1  SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/orcln1/orcln1/trace/orcln1_ora_20927.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       1  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       1  SQL statements in trace file.
       1  unique SQL statements in trace file.
      62  lines in trace file.
       0  elapsed seconds in trace file.

[oracle@OEL64BN1 oracle]$