{"id":1814,"date":"2011-12-11T08:12:51","date_gmt":"2011-12-11T13:12:51","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=1814"},"modified":"2011-12-11T08:12:51","modified_gmt":"2011-12-11T13:12:51","slug":"additional-cursor-trace-information-in-11-2-0","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2011\/12\/11\/additional-cursor-trace-information-in-11-2-0\/","title":{"rendered":"Additional cursor trace information in 11.2.0"},"content":{"rendered":"<p>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&#8217;t have access to the application source code.<\/p>\n<p>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. <\/p>\n<p>For example, assume we run the python script below&#8230;<\/p>\n<pre lang=\"python\">\r\n#!\/home\/oracle\/local\/bin\/python\r\n\r\nimport cx_Oracle\r\n\r\nconn = cx_Oracle.connect(\"rep\",\"rep\")\r\n\r\ncursor = conn.cursor()\r\n\r\ncursor.execute(\"alter session set events '10046 trace name context forever, level 12'\")\r\n\r\nfor i in range(50):\r\n  cursor = conn.cursor()\r\n  cursor.execute(\"select * from dual\")\r\n  cursor.close()\r\n\r\nconn.close()\r\n<\/pre>\n<p>As you may expect, you will see several PARSE and CLOSE calls, since that is exactly what we have requested.<\/p>\n<pre lang=\"text\">\r\nPARSE #47485481263416:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638063\r\nEXEC #47485481263416:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638086\r\nWAIT #47485481263416: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638104\r\nFETCH #47485481263416:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1322595369638134\r\nWAIT #47485481263416: nam='SQL*Net message from client' ela= 53 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638211\r\nCLOSE #47485481263416:c=0,e=3,dep=0,type=3,tim=1322595369638231\r\nPARSE #47485481263416:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638256\r\nEXEC #47485481263416:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=272002086,tim=1322595369638280\r\nWAIT #47485481263416: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638297\r\nFETCH #47485481263416:c=0,e=14,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=272002086,tim=1322595369638326\r\nWAIT #47485481263416: nam='SQL*Net message from client' ela= 52 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322595369638402\r\nCLOSE #47485481263416:c=0,e=3,dep=0,type=3,tim=1322595369638422\r\n<\/pre>\n<p>If we run something similar to this in PLSQL&#8230;<\/p>\n<pre lang=\"plsql\">\r\nSQL> begin\r\n  2    for i in 1..10 loop\r\n  3      for cur in (select * from dual) loop\r\n  4        null;\r\n  5      end loop;\r\n  6    end loop;\r\n  7  end;\r\n  8  \/\r\n\r\nPL\/SQL procedure successfully completed.\r\n<\/pre>\n<p>&#8230;we will see several CLOSE calls, but we won&#8217;t see the PARSE calls other than the first one, which is good.<\/p>\n<pre lang=\"text\">\r\nPARSE #22590940:c=9998,e=11478,p=1,cr=3,cu=0,mis=1,r=0,dep=1,og=1,plh=272002086,tim=1323607968465315\r\nEXEC #22590940:c=0,e=56,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968465513\r\nWAIT #22590940: nam='db file sequential read' ela= 20561 file#=1 block#=928 blocks=1 obj#=116 tim=1323607968486307\r\nWAIT #22590940: nam='db file sequential read' ela= 1120 file#=1 block#=929 blocks=1 obj#=116 tim=1323607968487710\r\nFETCH #22590940:c=0,e=22221,p=2,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968487843\r\nSTAT #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)'\r\nCLOSE #22590940:c=0,e=8,dep=1,type=3,tim=1323607968488139\r\nEXEC #22590940:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968488293\r\nFETCH #22590940:c=0,e=72,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968488449\r\nCLOSE #22590940:c=0,e=5,dep=1,type=3,tim=1323607968488531\r\nEXEC #22590940:c=0,e=33,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1323607968488666\r\nFETCH #22590940:c=0,e=56,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1323607968488785\r\nCLOSE #22590940:c=0,e=5,dep=1,type=3,tim=1323607968488863\r\n<\/pre>\n<p>If we run a python script similar to what we did earlier, but don&#8217;t close our cursor&#8230;<\/p>\n<pre lang=\"python\">\r\n#!\/home\/oracle\/local\/bin\/python\r\n\r\nimport cx_Oracle\r\n\r\nconn = cx_Oracle.connect(\"rep\",\"rep\")\r\n\r\ncursor = conn.cursor()\r\n\r\ncursor.execute(\"alter session set events '10046 trace name context forever, level 12'\")\r\n\r\ncursor.prepare(\"begin for cur in (select * from dual) loop null; end loop; end;\")\r\n\r\nfor i in range(50):\r\n  cursor.execute(\"begin for cur in (select * from dual) loop null; end loop; end;\")\r\n\r\ncursor.close()\r\nconn.close()\r\n<\/pre>\n<p>&#8230;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&#8230;<\/p>\n<pre lang=\"text\">\r\nPARSE #47704241137000:c=0,e=36,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012301\r\nEXEC #47704241137000:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012375\r\nFETCH #47704241137000:c=0,e=82,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012481\r\nSTAT #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)'\r\nCLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012603\r\nEXEC #47704241021240:c=0,e=557,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1322596587012653\r\nWAIT #47704241021240: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012674\r\nWAIT #47704241021240: nam='SQL*Net message from client' ela= 21 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012709\r\nEXEC #47704241137000:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012756\r\nFETCH #47704241137000:c=0,e=20,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012791\r\nCLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012817\r\nEXEC #47704241021240:c=0,e=106,p=0,cr=2,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1322596587012832\r\nWAIT #47704241021240: nam='SQL*Net message to client' ela= 0 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012850\r\nWAIT #47704241021240: nam='SQL*Net message from client' ela= 12 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1322596587012875\r\nEXEC #47704241137000:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=272002086,tim=1322596587012914\r\nFETCH #47704241137000:c=0,e=18,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=1,plh=272002086,tim=1322596587012946\r\nCLOSE #47704241137000:c=0,e=1,dep=1,type=3,tim=1322596587012970\r\n<\/pre>\n<p>It should be much easier to identify cursor leaks with this trace enhancement.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>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&hellip;<\/p>\n<p class=\"more-link-p\"><a class=\"more-link\" href=\"http:\/\/appcrawler.com\/wordpress\/2011\/12\/11\/additional-cursor-trace-information-in-11-2-0\/\">Read more &rarr;<\/a><\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_mi_skip_tracking":false,"footnotes":""},"categories":[19,22,26],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1814"}],"collection":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/comments?post=1814"}],"version-history":[{"count":17,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1814\/revisions"}],"predecessor-version":[{"id":1835,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/1814\/revisions\/1835"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=1814"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=1814"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=1814"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}