How do I get my trace files on a db-as-a-service

Yeah, sure it would be cool to crank up some big time powered VM’s in the cloud and let rip, but the reality is – if you’re starting out on a cloud exploration, you probably want to (initially at least) just dip your toes in the water and start with something small.  For example, if I wanted to play with 12c Release 2, I can just sign up for an Exadata Express service so I can explore the new features without breaking the bank.

But whatever the need, accessing a database as a service as opposed to a server, there’s often that fear of “handing over the reins”, that is, that I’ll not be able to do the things I want to do, especially when it comes to OS level access.  And for a developer or DBA, perhaps a thing that might raise alarm bells is: “How will I access my trace files ?”

Well, in 12c Release 2, there’s two nifty new views to help out here.  You can access trace file information directly from the database.  Here’s a simple example


SQL> desc V$DIAG_TRACE_FILE
 Name                          Null?    Type
 ----------------------------- -------- --------------------
 ADR_HOME                               VARCHAR2(444)
 TRACE_FILENAME                         VARCHAR2(68)
 CHANGE_TIME                            TIMESTAMP(3) WITH TIME ZONE
 MODIFY_TIME                            TIMESTAMP(3) WITH TIME ZONE
 CON_ID                                 NUMBER


SQL> select TRACE_FILENAME
  2  from   V$DIAG_TRACE_FILE
  3  order by 1;

TRACE_FILENAME
-----------------------------------------
db122_cjq0_32100.trc
db122_cjq0_3602.trc
db122_cjq0_3736.trc
db122_cjq0_6044.trc
db122_cjq0_8937.trc
db122_m001_20300.trc
db122_m001_21807.trc
db122_ora_10158.trc
db122_ora_5351.trc
db122_p000_32038.trc
db122_p000_3526.trc
db122_p000_3703.trc
db122_p000_4101.trc
db122_p000_5002.trc
db122_p000_6036.trc
db122_p000_8848.trc
...
...

And once I’ve identified a trace file that I’m interested in, I can grab it contents just as easily.



SQL> desc V$DIAG_TRACE_FILE_CONTENTS
 Name                          Null?    Type
 ----------------------------- -------- --------------------
 ADR_HOME                               VARCHAR2(444)
 TRACE_FILENAME                         VARCHAR2(68)
 RECORD_LEVEL                           NUMBER
 PARENT_LEVEL                           NUMBER
 RECORD_TYPE                            NUMBER
 TIMESTAMP                              TIMESTAMP(3) WITH TIME ZONE
 PAYLOAD                                VARCHAR2(4000)
 SECTION_ID                             NUMBER
 SECTION_NAME                           VARCHAR2(64)
 COMPONENT_NAME                         VARCHAR2(64)
 OPERATION_NAME                         VARCHAR2(64)
 FILE_NAME                              VARCHAR2(64)
 FUNCTION_NAME                          VARCHAR2(64)
 LINE_NUMBER                            NUMBER
 THREAD_ID                              VARCHAR2(64)
 SESSION_ID                             NUMBER
 SERIAL#                                NUMBER
 CON_UID                                NUMBER
 CONTAINER_NAME                         VARCHAR2(30)
 CON_ID                                 NUMBER




SQL> select PAYLOAD
  2  from   V$DIAG_TRACE_FILE_CONTENTS
  3  where  TRACE_FILENAME = 'orcl12c_ora_4163.trc'
  4  order by LINE_NUMBER;

PAYLOAD
----------------------------------------------------------------------------------------------------------------------------------
Trace file /u01/app/oracle/diag/rdbms/orcl12c/orcl12c/trace/orcl12c_ora_4163.trc
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
Build label:    RDBMS_12.2.0.1.0_LINUX.X64_161003
ORACLE_HOME:    /u01/app/oracle/product/12.2/db_1
System name:    Linux
Node name:      vbgeneric
Release:        3.8.13-118.14.1.el7uek.x86_64
Version:        #2 SMP Mon Oct 31 17:32:03 PDT 2016
Machine:        x86_64
Instance name: orcl12c
Redo thread mounted by this instance: 1
Oracle process number: 49
Unix process pid: 4163, image: oracle@vbgeneric


*** 2017-01-22T23:53:13.661980-05:00 (ORCL(3))

*** SESSION ID:(48.50034) 2017-01-22T23:53:13.662038-05:00
*** CLIENT ID:() 2017-01-22T23:53:13.662050-05:00
*** SERVICE NAME:(orcl) 2017-01-22T23:53:13.662059-05:00
*** MODULE NAME:(SQL*Plus) 2017-01-22T23:53:13.662069-05:00
*** ACTION NAME:() 2017-01-22T23:53:13.662079-05:00
*** CLIENT DRIVER:(SQL*PLUS) 2017-01-22T23:53:13.662087-05:00
*** CONTAINER ID:(3) 2017-01-22T23:53:13.662097-05:00

WAIT #139958764906240: nam='PGA memory operation' ela= 102 p1=0 p2=0 p3=0 obj#=1376 tim=656737684
WAIT #139958764906240: nam='SQL*Net message to client' ela= 38 driver id=1413697536 #bytes=1 p3=0 obj#=1376 tim=656738633
WAIT #139958764906240: nam='SQL*Net message from client' ela= 2608 driver id=1413697536 #bytes=1 p3=0 obj#=1376 tim=656741328
CLOSE #139958764906240:c=0,e=110,dep=0,type=1,tim=656741672
=====================
PARSING IN CURSOR #139958764708168 len=36 dep=0 uid=117 oct=47 lid=117 tim=656745298 hv=4128301241 ad='7429cdd8' sqlid='5t10uu7v11s5t'

BEGIN DBMS_OUTPUT.ENABLE(NULL); END;
END OF STMT
PARSE #139958764708168:c=3000,e=3496,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=656745290
EXEC #139958764708168:c=0,e=147,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=656745624
WAIT #139958764708168: nam='SQL*Net message to client' ela= 10 driver id=1413697536 #bytes=1 p3=0 obj#=1376 tim=656745713
WAIT #139958764708168: nam='SQL*Net message from client' ela= 5605 driver id=1413697536 #bytes=1 p3=0 obj#=1376 tim=656751369
CLOSE #139958764708168:c=0,e=64,dep=0,type=0,tim=656751853
=====================
PARSING IN CURSOR #139958859515432 len=332 dep=1 uid=0 oct=3 lid=0 tim=656752148 hv=2698389488 ad='614a4b08' sqlid='acmvv4fhdc9zh'


select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2, spare3, signature, spare7, spare8, spare9, nvl
(dflcollid, 16382), creappid, creverid, modappid, modverid, crepatchid, modpatchid from obj$ where owner#=:1 and name=:2 and names
pace=:3 and remoteowner is null and linkname is null and subname is null

END OF STMT
EXEC #139958859515432:c=1000,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=813480514,tim=656752148
FETCH #139958859515432:c=0,e=32,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=4,plh=813480514,tim=656752256
CLOSE #139958859515432:c=0,e=2,dep=1,type=3,tim=656752308
EXEC #139958859515432:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=813480514,tim=656752540
FETCH #139958859515432:c=0,e=36,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=813480514,tim=656752629
CLOSE #139958859515432:c=0,e=7,dep=1,type=3,tim=656752675
=====================
PARSING IN CURSOR #139958765170592 len=868 dep=3 uid=0 oct=3 lid=0 tim=656755217 hv=3633507567 ad='60fdfec8' sqlid='121ffmrc95v7g'


select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.di
stkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.
pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.
spare6,decode(i.pctthres$,null,null,mod(trunc(i.pctthres$/256),256)),nvl(i.evaledition#,1),nvl(i.unusablebefore#,0),nvl(i.unusable
beginning#,0), ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(intcols) unicols,min(t
o_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by en
abled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#

END OF STMT
EXEC #139958765170592:c=0,e=137,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=4,plh=2542797530,tim=656755214
FETCH #139958765170592:c=1000,e=235,p=0,cr=3,cu=0,mis=0,r=0,dep=3,og=4,plh=2542797530,tim=656755601
CLOSE #139958765170592:c=0,e=2,dep=3,type=3,tim=656755692
=====================
PARSING IN CURSOR #139958765274984 len=552 dep=3 uid=0 oct=3 lid=0 tim=656755788 hv=1798149220 ad='6148cc98' sqlid='9t4vxdppkv534'
...
...
...

Easy as that !

Where is my tracefile

As a developer, you might have have been reading about SQL trace. After all, we all want to be able to diagnose and improve the performance of the code we write. So if you’ve googled on Oracle performance, you will have no doubt stumbled upon SQL trace.

So if you’ve run “alter session set sql_trace = true”, or perhaps “DBMS_MONITOR.SESSION_TRACE_ENABLE”.  you’re probably itching to get your hands on that trace file.  The question is – where is it ?  And that is the subject of my next quick tip…Enjoy

https://youtu.be/Xoq3lvxUTmY

A little quiz on tkprof

I found this in a trace file recently

INSERT 
INTO T (X)
VALUES(:B1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       15      0.00       0.00          0          0          0           0
Execute     15      0.00       0.00          0          4         44           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       30      0.00       0.00          0          4         44           2

the obvious question being: How can I execute an insert-values 15 times and only insert 2 rows.

Background Information:

  • There are no triggers of any kind on the table, and no database-wide triggers that might impact the experiment
  • No ‘special interception code’ (eg row level security, views, query rewrite etc)
  • No errors are raised by any of the 15 inserts.
  • No indexes on the table