Home
image/camel.gif

The use of 'sstr' and 'tkp'


image/camel.gif


How to use automated trace session :



This example illustrate the use of the shortcuts 'sstr' & 'tkp' to set a user session in trace mode for 5 minutes and generate a tkprof for it. This case is typical of situations where you need to know what is happening with a session, whilst extracting the SQL from the sqlarea revealed not sufficient to determine the cause of the problem.

The other shortcuts used are :
  • 'psi' which is just a useful alias for 'ps -ef | grep $ORACLE_SID'
  • 'sl' which produces info like the session ID and session OS PID
  • 'sa' session_id which display the SQL that the session is currently running.
  • Notes: we could have also used sstv which set the session trace level to event 10046 at level 12


[ps -ef | grep oracle] : What 's the Hell, is doing this user ? 

testdev:/usr/local/smenu/tmp> psi
  oracle   336     1  0   Oct 09 ?        0:00 ora_pmon_SM_DVL
  oracle   338     1  1   Oct 09 ?       26:50 ora_dbwr_SM_DVL
  oracle   340     1  1   Oct 09 ?       24:18 ora_lgwr_SM_DVL
  oracle   342     1  0   Oct 09 ?        0:01 ora_smon_SM_DVL
  oracle   344     1  0   Oct 09 ?        0:00 ora_reco_SM_DVL
  oracle  3849     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
  oracle  3502     1  0   Oct 12 ?        0:17 oracleSM_DVL (LOCAL=NO)
  oracle  3506     1  0   Oct 12 ?        132:09 oracleSM_DVL (LOCAL=NO)
  oracle  3514     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
  oracle  3518     1  0   Oct 12 ?        0:01 oracleSM_DVL (LOCAL=NO)
  oracle  3526     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
  oracle 11072 10800  0 14:01:55 pts/20   0:00 grep SM_DVL
  oracle 10650     1  0 13:34:20 ?        0:02 oracleSM_DVL (LOCAL=NO)
  oracle  6403     1  0   Oct 13 ?        0:05 oracleSM_DVL (LOCAL=NO)
  oracle 11027     1  0 13:44:15 ?        0:10 oracleSM_DVL (LOCAL=NO)
  oracle  3713     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
  oracle  6399     1  0   Oct 13 ?        0:00 oracleSM_DVL (LOCAL=NO)
  oracle 11052     1  0 13:44:45 ?        0:07 oracleSM_DVL (LOCAL=NO)


[List sessions] : Using this command, we have enough info to link the os-pid to the session ID. 

testdev:/usr/local/smenu/tmp> sl
***************************************************************
 TIPS : If program column is not wide enough, You may increase
        the size of program column by typing : "sl 50"
***************************************************************

MACHINE testdev - ORACLE_SID : SM_DVL                   Page: 1

Date              -  Thursday  10th October   2005  14:22:53
Username          -  SYSTEM
Sessions          -  Generic info Overview


            Sess
USERNAME     ID  OSUSER   Serial  PID# OS-PPID   PROGRAM
---------- ----- ------- ------- ----- --------- ----------------------
orange       6 tester1    1,382   3506   3504     ?  @SM_DVL (TNS V1-V2)
orange       7 tester1    1,037   3502   3500     ?  @SM_DVL (TNS V1-V2)
orange       8 tester1    8,347   3713   3508     ?  @SM_DVL (TNS V1-V2)
orange       9 tester1       11   3514   3512  tagent@SM_DVL (TNS V1-V2)
orange      10 tester1        5   3518   3516     ?  @SM_DVL (TNS V1-V2)
orange      11 tester1      31   11027  11025     ?  @SM_DVL (TNS V1-V2)
orange      12 tester1       17   3526   3524     ?  @SM_DVL (TNS V1-V2)
orange      13 tester1   5,155   10650  10648     ?  @SM_DVL (TNS V1-V2)
orange      14 tester1   30,879   3849   3847     ?  @SM_DVL (TNS V1-V2)
orange      15 tester1   5,852   11052  11050     ?  @SM_DVL (TNS V1-V2)
orange      18 tester1   16,964   6399   6397     ?  @SM_DVL (TNS V1-V2)
orange      19 tester1    1,532   6403   6401     ?  @SM_DVL (TNS V1-V2)

13 rows selected.


We try to see what SQL is running using the shorcut sa [Session activity] with the Oracle Session ID: 

testdev:/usr/local/smenu/tmp> sa 6
MACHINE testdev - ORACLE_SID : SM_DVL                   Page: 1

Date              -  Monday    10th October   2005  14:40:20
Username          -  SYS
Session           -  Session Activity Overview


Sid  Osuser             Osuser       Program                        LOGON_TIME
---- ------------------ ------------ ------------------------------ ------------
36   DEV_OWNER         deved4      TOAD.exe                       10-oct 10:56


Sql in work area:

SQL  Addr     Sql
---- -------- --------------------------------------------------------------------------------
Curr 3FB545FC select level, operation||decode(options, null,'',' '||options)||  DECODE(ID,0,DE
              CODE(OPTIMIZER,NULL,'', ' Optimizer Mode=' ||OPTIMIZER)),        decode(object_n
              ame, null, ' ', object_owner || '.' || object_name),   decode(cardinality,null,'
                ',           decode(sign(cardinality-1000), -1, cardinality||'  ',
              decode(sign(cardinality-1000000), -1, trunc(cardinality/1000)||' K',
              decode(sign(cardinality-1000000000), -1, trunc(cardinality/1000000)||' M',
                           trunc(cardinality/1000000000)||' G')))) NumRows,     decode(bytes,n
              ull,' ',           decode(sign(bytes-1024), -1, bytes||'  ',            decode(s
              ign(bytes-1048576), -1, trunc(bytes/1024)||' K',            decode(sign(bytes-10
              73741824), -1, trunc(bytes/1048576)||' M',                   trunc(bytes/1073741
              824)||'G')))) bytes,     decode(cost,null,' ',           decode(sign(cost-100000
              00), -1, cost||'  ',            decode(sign(cost-1000000000), -1, trunc(cost/100
              0000)||' M',                   trunc(co

Prev 3FB545FC select level, operation||decode(options, null,'',' '||options)||  DECODE(ID,0,DE
              CODE(OPTIMIZER,NULL,'', ' Optimizer Mode=' ||OPTIMIZER)),        decode(object_n
              ame, null, ' ', object_owner || '.' || object_name),   decode(cardinality,null,'
                ',           decode(sign(cardinality-1000), -1, cardinality||'  ',
              decode(sign(cardinality-1000000), -1, trunc(cardinality/1000)||' K',
              decode(sign(cardinality-1000000000), -1, trunc(cardinality/1000000)||' M',
                           trunc(cardinality/1000000000)||' G')))) NumRows,     decode(bytes,n
              ull,' ',           decode(sign(bytes-1024), -1, bytes||'  ',            decode(s
              ign(bytes-1048576), -1, trunc(bytes/1024)||' K',            decode(sign(bytes-10
              73741824), -1, trunc(bytes/1048576)||' M',                   trunc(bytes/1073741
              824)||'G')))) bytes,     decode(cost,null,' ',           decode(sign(cost-100000
              00), -1, cost||'  ',            decode(sign(cost-1000000000), -1, trunc(cost/100
              0000)||' M',                   trunc(co

                                                                                     Total
                                        Disk       Rows                             Session
SQL  Buffer Gets Executions Gets/Exec   Reads    Processed       SORTS PARSE_CALLS Hard Parse   CPU_TIME
---- ----------- ---------- --------- --------- ----------- ---------- ----------- ---------- ----------
Curr       20869         79       264      1354         251        268          79         31        .45
Prev                                                               268          79         31        .45

Event and his latch wait:
Humm.. what we obtained is obviously not sufficient. So we need to set the trace into this session and generate a tkproof : We can do it quickly using the sstr and tkp command from Smenu.


We set the trace mode in Oracle session id=6 whose unis PID=3506 

testdev:/usr/local/smenu/tmp> sstr
 Oracle Session to trace
 ---------------------------

 1 : oracle  3506    1  0   Oct 12 ?   0:00 oracleSM_DVL (LOCAL=NO)
 2 : oracle  3502    1  0   Oct 12 ?   0:17 oracleSM_DVL (LOCAL=NO)
 3 : oracle  3849    1  0   Oct 12 ?   2:14 oracleSM_DVL (LOCAL=NO)
 4 : oracle  3514    1  0   Oct 12 ?   0:00 oracleSM_DVL (LOCAL=NO)
 5 : oracle  3518    1  0   Oct 12 ?   0:01 oracleSM_DVL (LOCAL=NO)
 6 : oracle  3526    1  0   Oct 12 ?   0:00 oracleSM_DVL (LOCAL=NO)
 7 : oracle 10650    1  0 13:34:20 ?   0:02 oracleSM_DVL (LOCAL=NO)
 8 : oracle  6403    1  0   Oct 13 ?   0:05 oracleSM_DVL (LOCAL=NO)
 9 : oracle 11027    1  0 13:44:15 ?   0:10 oracleSM_DVL (LOCAL=NO)
 10: oracle  3713    1  0   Oct 12 ?   0:00 oracleSM_DVL (LOCAL=NO)
 11: oracle  6399    1  0   Oct 13 ?   0:00 oracleSM_DVL (LOCAL=NO)
 12: oracle 11052    1  0 13:44:45 ?   0:07 oracleSM_DVL (LOCAL=NO)

 e   : exit

 If you want to trace off, then type the number finished by n
 ==> 1 (trace on)    ;   ==> 1n (trace off)

 Select the session you want to trace, 'e' to exit ==> 1


Next we have : 


Get Oracle SID and Serial
 =========================
Doing : execute sys.dbms_system.set_sql_trace_in_session(6,1382,TRUE)

PL/SQL procedure successfully completed.


Now it is coffee time. Let's Oracle collect data for us. After 5 minutes (depending on your pace the trace file is generated) we have gathered enough informations, so we set the trace off into the session and go for the next step : the explain plan. 

testdev:/usr/local/smenu/tmp> sstr

 Oracle Session to trace
 ---------------------------

 1 : oracle  3506     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
 2 : oracle  3502     1  0   Oct 12 ?        0:17 oracleSM_DVL (LOCAL=NO)
 3 : oracle  3849     1  0   Oct 12 ?        2:14 oracleSM_DVL (LOCAL=NO)
 4 : oracle  3514     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
 5 : oracle  3518     1  0   Oct 12 ?        0:01 oracleSM_DVL (LOCAL=NO)
 6 : oracle  3526     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
 7 : oracle 10650     1  0 13:34:20 ?        0:02 oracleSM_DVL (LOCAL=NO)
 8 : oracle  6403     1  0   Oct 13 ?        0:05 oracleSM_DVL (LOCAL=NO)
 9 : oracle 11027     1  0 13:44:15 ?        0:10 oracleSM_DVL (LOCAL=NO)
 10: oracle  3713     1  0   Oct 12 ?        0:00 oracleSM_DVL (LOCAL=NO)
 11: oracle  6399     1  0   Oct 13 ?        0:00 oracleSM_DVL (LOCAL=NO)
 12: oracle 11052     1  0 13:44:45 ?        0:07 oracleSM_DVL (LOCAL=NO)

 e   : exit

 If you want to trace off, then type the number finished by n
 ==> 1 (trace on)    ;   ==> 1n (trace off)

 Select the session you want to trace, 'e' to exit ==> 1n
    Are you sure you want  to trace OFF 3506  (y/n) ? y
 Get Oracle SID and Serial
 =========================
Doing : execute sys.dbms_system.set_sql_trace_in_session(6,1382,FALSE)

PL/SQL procedure successfully completed.

test:/usr/local/smenu/tmp>


Now it is time to generate the tkprof. We will use for that the shortcut tkp. It connects immediatly into the DB, retrieves from the v$parameter view the path of USER_DUMP_DEST, disconnect, go to the directory and generate a list of all trace files, the last at top : 

testdev:/usr/local/smenu/tmp> tkp

Retrieveing User demp dest :  got it !
====> /app/oracle/admin/SM_DVL/udump
Changing path to user_dump_dest directories

*********************************************************************
    Tkprof parameters :     -Explain plan  : NO
                            -Aggregate     : NO
                            -Sys           : NO

    Append a 'v' to the number, if you want only see the trc file
 *********************************************************************

 Trace file to process :

 1 : -rw-r-----   1 oracle   dba    21840 Oct 14 14:08 sm_dvl_ora_3506.trc
 2 : -rw-r-----   1 oracle   dba     2232 Sep 27 09:36 sm_dvl_ora_2404.trc
 3 : -rw-r-----   1 oracle   dba      557 Sep  4 10:21 sm_dvl_ora_1844.trc
 4 : -rw-r-----   1 oracle   dba      588 Sep  2 06:00 sm_dvl_ora_1357.trc
 5 : -rw-r-----   1 oracle   dba     1008 Jul 22 18:20 sm_dvl_ora_8545.trc
 6 : -rw-r-----   1 oracle   dba      568 Jun 28 10:48 sm_dvl_ora_2710.trc
 7 : -rw-r-----   1 oracle   dba    54735 Mar 23  1999 sm_dvl_ora_1422.trc
 8 : -rw-r-----   1 oracle   dba   355042 Mar 23  1999 sm_dvl_ora_1327.trc
 9 : -rw-r-----   1 oracle   dba   356980 Mar 23  1999 sm_dvl_ora_6047.trc


 p   : explain plan ==> YES
 a   : Aggregate    ==> YES
 s   : SYS          ==> YES

 e   : exit

 Select a trace file to process  ==> P

Note the defaults values at start. As we want to generate an explain plan, we need to set the "EXPLAIN Plan" to Yes.


Now it is done, so we select the last trc file. If we have any doubt, it is possible to view the file before by typing '1v'. It will have as effect to enter in view mode in the trace file number 1. When finished we will be put in the same screen. 

 *********************************************************************
    Tkprof parameters :     -Explain plan  : YES
                            -Aggregate     : NO
                            -Sys           : NO

    Append a 'v' to the number, if you want only see the trc file
 *********************************************************************

 Trace file to process :

 1 : -rw-r-----   1 oracle   dba    21840 Oct 14 14:08 sm_dvl_ora_3506.trc
 2 : -rw-r-----   1 oracle   dba     2232 Sep 27 09:36 sm_dvl_ora_2404.trc
 3 : -rw-r-----   1 oracle   dba      557 Sep  4 10:21 sm_dvl_ora_1844.trc
 4 : -rw-r-----   1 oracle   dba      588 Sep  2 06:00 sm_dvl_ora_1357.trc
 5 : -rw-r-----   1 oracle   dba     1008 Jul 22 18:20 sm_dvl_ora_8545.trc
 6 : -rw-r-----   1 oracle   dba      568 Jun 28 10:48 sm_dvl_ora_2710.trc
 7 : -rw-r-----   1 oracle   dba    54735 Mar 23  1999 sm_dvl_ora_1422.trc
 8 : -rw-r-----   1 oracle   dba   355042 Mar 23  1999 sm_dvl_ora_1327.trc
 9 : -rw-r-----   1 oracle   dba   356980 Mar 23  1999 sm_dvl_ora_6047.trc


 p   : explain plan ==> NO
 a   : Aggregate    ==> YES
 s   : SYS          ==> YES

 e   : exit

 Select a trace file to process  ==> 1


We must now decide if we run the explain plan as our default user (defined in smenu.env) our as the owner of the session. Hapilly we know the password of this user, so : 

 DO you want  to use default user [SYS/change_on_install] (y/n) ?  [Y]  N
 Input the User name and its password in the form : "USER/PASSWD"
===> orange/miamiam
 Are you sure you want to run tkprof on sm_dvl_ora_3506.trc y/n)? y


Here we are : the explain paln has been generated, and we are directly in edit mode in the explain plan file : 517 lines. 

TKPROF: Release 9.2.0.4 - Production on Thu Oct 14 14:09:52 2005

Copyright (c) Oracle Corporation 1979, 2005.  All rights reserved.

Trace file: sm_dvl_ora_3506.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 owner#,name,namespace,remoteowner,linkname
from
 obj$ where obj#=:1


call     count       cpu    elapsed    disk    query     current  rows
------- ------  -------- ---------- ------- ------------ ------- -------
Parse        8      0.00       0.00       0       0       0          0
Execute     15      0.00       0.00       0       0       0          0
Fetch       15      0.00       0.00       6      45       0         15
------- ------  -------- ---------- ------- ------------ ------- -------
total       38      0.00       0.00       6      45       0         15

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: orange   (recursive depth: 1)

Rows     Execution Plan
 ********************************************************************    
    Tkprof parameters :     -Explain plan  : YES

Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   GOAL: CHOOSE
      0   TABLE ACCESS (BY ROWID) OF 'OBJ$'
      0    INDEX (UNIQUE SCAN) OF 'I_OBJ1' (UNIQUE)

********************************************************************
"sm_dvl_ora_3506.txt" 517 lines, 22111 characters






bpolarsk@yahoo.com

Last Update : 10-Oct-2005