Oracle has added a lot of additional trace output in the 10046 optimizer trace files. As I have posted previously, I find the output in these files to be useful not only for troubleshooting performance issues, but also understanding the business flow of the application in cases where I don’t have access to the application source code.
I noticed in the raw trace file that it now includes, among other things, CLOSE statements as it relates to a particular cursor. I thought this was interesting, as we no longer have to total PARSE calls for a given statement, but can see the actual occurrence of each CLOSE.
For example, assume we run the python script below…
#!/home/oracle/local/bin/python
import cx_Oracle
conn = cx_Oracle.connect("rep","rep")
cursor = conn.cursor()
cursor.execute("alter session set events '10046 trace name context forever, level 12'")
for i in range(50):
cursor = conn.cursor()
cursor.execute("select * from dual")
cursor.close()
conn.close()
As you may expect, you will see several PARSE and CLOSE calls, since that is exactly what we have requested.
PARSE #47485481263416:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638063
EXEC #47485481263416:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638086
WAIT #47485481263416: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638104
FETCH #47485481263416:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1322595369638134
WAIT #47485481263416: nam='SQL*Net message from client' ela= 53 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638211
CLOSE #47485481263416:c=0,e=3,dep=0,type=3,tim=1322595369638231
PARSE #47485481263416:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638256
EXEC #47485481263416:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638280
WAIT #47485481263416: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638297
FETCH #47485481263416:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1322595369638326
WAIT #47485481263416: nam='SQL*Net message from client' ela= 52 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638402
CLOSE #47485481263416:c=0,e=3,dep=0,type=3,tim=1322595369638422
If we run something similar to this in PLSQL…
SQL> begin
2 for i in 1..10 loop
3 for cur in (select * from dual) loop
4 null;
5 end loop;
6 end loop;
7 end;
8 /
PL/SQL procedure successfully completed.
…we will see several CLOSE calls, but we won’t see the PARSE calls other than the first one, which is good.
PARSE #22590940:c=9998,e=11478,p=1,cr=3,cu=0,mis=1,r=0,dep=1,og=1,plh=272002086,tim=1323607968465315
EXEC #22590940:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968465513
WAIT #22590940: nam='db file sequential read' ela= 20561 file#=1 block#=928 blocks=1 obj#=116 tim=1323607968486307
WAIT #22590940: nam='db file sequential read' ela= 1120 file#=1 block#=929 blocks=1 obj#=116 tim=1323607968487710
FETCH #22590940:c=0,e=22221,p=2,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968487843
STAT #22590940 id=1 cnt=1 pid=0 pos=1 obj=116 op='TABLE ACCESS FULL DUAL (cr=2 pr=2 pw=0 time=22181 us cost=2 size=2 card=1)'
CLOSE #22590940:c=0,e=8,dep=1,type=3,tim=1323607968488139
EXEC #22590940:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968488293
FETCH #22590940:c=0,e=72,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968488449
CLOSE #22590940:c=0,e=5,dep=1,type=3,tim=1323607968488531
EXEC #22590940:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968488666
FETCH #22590940:c=0,e=56,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968488785
CLOSE #22590940:c=0,e=5,dep=1,type=3,tim=1323607968488863
If we run a python script similar to what we did earlier, but don’t close our cursor…
#!/home/oracle/local/bin/python
import cx_Oracle
conn = cx_Oracle.connect("rep","rep")
cursor = conn.cursor()
cursor.execute("alter session set events '10046 trace name context forever, level 12'")
cursor.prepare("begin for cur in (select * from dual) loop null; end loop; end;")
for i in range(50):
cursor.execute("begin for cur in (select * from dual) loop null; end loop; end;")
cursor.close()
conn.close()
…we see something similar to what we saw in the PL/SQL output, with the addition of the SQL*Net wait events since the code is executing on the client…
PARSE #47704241137000:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012301
EXEC #47704241137000:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012375
FETCH #47704241137000:c=0,e=82,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012481
STAT #47704241137000 id=1 cnt=1 pid=0 pos=1 obj=258 op='TABLE ACCESS FULL DUAL (cr=2 pr=0 pw=0 time=62 us cost=2 size=2 card=1)'
CLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012603
EXEC #47704241021240:c=0,e=557,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1322596587012653
WAIT #47704241021240: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012674
WAIT #47704241021240: nam='SQL*Net message from client' ela= 21 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012709
EXEC #47704241137000:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012756
FETCH #47704241137000:c=0,e=20,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012791
CLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012817
EXEC #47704241021240:c=0,e=106,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1322596587012832
WAIT #47704241021240: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012850
WAIT #47704241021240: nam='SQL*Net message from client' ela= 12 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012875
EXEC #47704241137000:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012914
FETCH #47704241137000:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012946
CLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012970
It should be much easier to identify cursor leaks with this trace enhancement.