New Information in SQL Trace Files

During some tests with patchset 11.1.0.7 (which is presently available for Linux 32-bit and 64-bit only) I noticed something new in the SQL trace files.

Let’s see what is the difference if I run the following statements with and without the patchset:

execute dbms_monitor.session_trace_enable(waits=>FALSE)
SELECT 'Hello world!' FROM dual;
execute dbms_monitor.session_trace_disable

The relevant part of the trace file is the following:

• 11.1.0.6.0

PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018499653282 hv=1643260990 ad='6e1e6ac8' sqlid='7a45d99hz4b1y'
SELECT 'Hello world!' FROM dual
END OF STMT
PARSE #1:c=1000,e=79,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653279
EXEC #1:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1222018499653403
FETCH #1:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1222018499653472
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1222018499653788

• 11.1.0.7.0

PARSING IN CURSOR #1 len=31 dep=0 uid=0 oct=3 lid=0 tim=1222018585374765 hv=1643260990 ad='6f5af5e0' sqlid='7a45d99hz4b1y'
SELECT 'Hello world!' FROM dual
END OF STMT
PARSE #1:c=999,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=1222018585374765
FETCH #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=1222018585374765
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
FETCH #1:c=1000,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=1388734953,tim=1222018585396826
CLOSE #1:c=0,e=0,dep=0,type=0,tim=1222018585396826

You spotted the difference?

Yes! There are two fetches. But, what I wanted to point out with this post, is the new line beginning with CLOSE.