Minor Bug in the Trace File Browser

Toad for Oracle
1

Hi John (I’m assuming that it will be you who gets this!)

  • TOAD 13.0.0.80 64bit With DB Admin Module.
  • Windows 7 64bit
  • Oracle 11.2.0.4 on AIX.
    I was using the trace file browser to look at a trace file, and I noticed a slight foible. I’ve attached, hopefully, a small trace that shows the problem. Server names etc have been obfuscated to protect me!

In the TFB, lower panel, SQL Statement tab, bind details on the left side, one of the binds is listed as having a NULL value, when in fact it is a varchar2 with a data format string in it. However, if I look on the right side, and check to “substitute variables back into SQL” then it does appear with the correct value.

This contrived statement shows the problem:

select to_char(to_date(:dte, :fmt), :fmt) from dual

It is, of course, a minor problem.

Cheers,

Norm. [TeamT]

2

Hmm, doesn’t like my trace file. Luckily it’s small:

Trace file forJohn.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, Automatic Storage Management, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /opt/oracle/product/11.2.0.4
System name: AIX
Node name: NormsServer
Release: 1
Version: 7
Machine: 00C4E1854C00
Instance name: ORCL11G
Redo thread mounted by this instance: 1
Oracle process number: 218
Unix process pid: 4326254, image: oracle@normsserver

*** 2018-06-22 15:30:33.330
*** SESSION ID:(214.64787) 2018-06-22 15:30:33.330
*** CLIENT ID:() 2018-06-22 15:30:33.330
*** SERVICE NAME:(ORCL11G) 2018-06-22 15:30:33.330
*** MODULE NAME:(SQL*Plus) 2018-06-22 15:30:33.330
*** ACTION NAME:() 2018-06-22 15:30:33.330

=====================
PARSING IN CURSOR #4573856920 len=73 dep=0 uid=285 oct=3 lid=285 tim=24369745777599 hv=2475802919 ad=‘7000107617b1290’ sqlid=‘2w33pkk9t3h97’
select /+ straight binds / to_char(to_date(:dte, :fmt), :fmt) from dual
END OF STMT
PARSE #4573856920:c=234,e=424,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=24369745777599
BINDS #4573856920:
Bind#0
oacdty=01 mxl=32(25) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=46 siz=64 off=0
kxsbbbfp=1109f7ba0 bln=32 avl=19 flg=05
value=“22/06/2018 07:04:30”
Bind#1
oacdty=01 mxl=32(25) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=46 siz=0 off=32
kxsbbbfp=1109f7bc0 bln=32 avl=21 flg=01
value=“dd/mm/yyyy hh24:mi:ss”
Bind#2
No oacdef for this bind.
EXEC #4573856920:c=605,e=998,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1546270724,tim=24369745778674
WAIT #4573856920: nam='SQLNet message to client’ ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=24369745778742
FETCH #4573856920:c=21,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1546270724,tim=24369745778807
STAT #4573856920 id=1 cnt=1 pid=0 pos=1 obj=0 op=‘FAST DUAL (cr=0 pr=0 pw=0 time=1 us cost=2 size=0 card=1)’
WAIT #4573856920: nam='SQLNet message from client’ ela= 37634 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=24369745816515
FETCH #4573856920:c=2,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1546270724,tim=24369745816609
WAIT #4573856920: nam=‘SQLNet message to client’ ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=24369745816636
WAIT #4573856920: nam='SQLNet message from client’ ela= 33415 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=24369745850075
CLOSE #4573856920:c=4,e=7,dep=0,type=0,tim=24369745850161

3

Thanks Norm. I’m logging this for now but will come back to it.

4

Hi Norm,

Was the format of that file changed in any way? I’m expecting a single space before the “Bind#n” lines, and a double space before the lines underneath it.

-John

5

Oh, just to be clear…I mean I’m looking for this:

trace.jpeg

6

Oh, I understand now. The forum stripped out the spaces. And the problem you are referring to is the fact that the Trace File Browser doesn’t give any info about the 3rd bind!

It’s due to the “No oacdef for this bind” that oracle gives us with repeated binds in a query, instead of repeating the bind data.

7

Hi John,

apologies, I tried to attach my trace file as an attachment via the forum, but it rejected me for some reason. I then copied and pasted it, as it was small, but as you note, the forum stripped the spaces out. Apologies for that, I hadn’t noticed when I posted it as that post required moderation. My first post on any subject is ok, my second and subsequent need moderation. I must be a bad influence!

I realise the problem is due to the “no ocadef…” as I had to cope with that in my TraceMiner2 utility. (I shall avoid shamelessly posting the download URL!).

Have you noticed though, that in some trace files, where there are two or more uses of the same bind, that sometimes, Oracle sets up a proper bind section in the trace, for the second usage? Consistency? Who needs it! There’s an example in the trace file I sent you earlier, at line 153. Luckily Bind#1 and Bind#2 have completely identical setups.

I love trace files, so much that can go wrong! [;)]

8

Hi Norm,

My first post on any subject is ok, my second and subsequent need moderation. I must be a bad influence!

Yeah, the forum doesn't like back to back posts from the same person.

OK, it's fixed for next beta. I even tested it with a more complicated repetition - "select :a, :b, :c, :f, :f, :f, :aa, 0, 1, :x, :f, :a from dual" and it seems to work now in both substitution and the tree.

I've never noticed the inconsistencies of "no oacdef for this bind". I wonder what's up with that? Maybe if the 2nd one has a different case? That would probably be too easy.

9

Evening John,

Thanks very much for a quick turn around.

Re the inconsistencies, the one I mentioned is in an anonymous block - maybe that has something to do with it, but I don’t know myself. Yet!

Cheers.