{"id":633,"date":"2010-01-26T14:20:31","date_gmt":"2010-01-26T19:20:31","guid":{"rendered":"http:\/\/appcrawler.com\/wordpress\/?p=633"},"modified":"2011-07-06T09:35:57","modified_gmt":"2011-07-06T14:35:57","slug":"bug-in-cx_oracle-cursorfetchmanyall","status":"publish","type":"post","link":"http:\/\/appcrawler.com\/wordpress\/2010\/01\/26\/bug-in-cx_oracle-cursorfetchmanyall\/","title":{"rendered":"cx_Oracle cursor fetching behaviour"},"content":{"rendered":"

I have noticed this over the past few months, and think I still may be missing something. Given the following code…<\/p>\n

\r\n#!\/home\/oracle\/local\/bin\/python\r\nimport cx_Oracle\r\nimport sys\r\n\r\ncon = cx_Oracle.connect(\"howards\",\"******\",\"perfrac\")\r\ncon.cursor().execute(\"alter session set events '10046 trace name context forever, level 12'\");\r\ncursor = con.cursor()\r\ncursor.arraysize = 1000\r\ntry:\r\n  cursor.execute(\"drop table t\")\r\nexcept:\r\n  pass\r\ncursor.execute(\"create table t(c number)\")\r\ncursor.execute(\"insert into t select rownum from user_objects where rownum <= 5\")\r\ncon.commit()\r\ncursor.execute(\"select * from t\")\r\nfor row in cursor.fetchall():\r\n  print row[0]\r\ncursor.close()\r\ncon.close()\r\n<\/pre>\n
...which is then executed as follows...<\/p>\n
\r\nemgrid01:oracle:emprod1:\/home\/oracle>.\/testFetch.py\r\n1\r\n2\r\n3\r\n4\r\n5\r\nemgrid01:oracle:emprod1:\/home\/oracle>vi testFetch.py\r\n<\/pre>\n
...I get the following the resulting trace file...<\/p>\n
\r\nPARSING IN CURSOR #1 len=15 dep=0 uid=95 oct=3 lid=95 tim=1234892270413286 hv=1134051363 ad='aeab5dd8'\r\nselect * from t\r\nEND OF STMT\r\nPARSE #1:c=0,e=686,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1234892270413282\r\nBINDS #1:\r\nEXEC #1:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1234892270413373\r\nWAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413404\r\nFETCH #1<\/B>:c=0,e=50,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1234892270413507\r\nWAIT #1: nam='SQL*Net message from client' ela= 323 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413862\r\nWAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413891\r\nFETCH #1<\/B>:c=0,e=34,p=0,cr=5,cu=0,mis=0,r=4,dep=0,og=4,tim=1234892270413918\r\nWAIT #1: nam='SQL*Net message from client' ela= 316 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414281\r\nSTAT #1 id=1 cnt=5 pid=0 pos=1 obj=258234 op='TABLE ACCESS FULL T (cr=8 pr=0 pw=0 time=37 us)'\r\nXCTEND rlbk=1, rd_only=1\r\nWAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414363\r\nWAIT #0: nam='SQL*Net message from client' ela= 152 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414528\r\nXCTEND rlbk=0, rd_only=1\r\n<\/pre>\n
Why are there two fetches?  Only 410 microseconds elapsed between the first and second fetch, so it isn't a huge deal.  However, it does limit scalability.<\/p>\n
I then tried the code above, but commented out the for row in fetchall():<\/code> piece.  I found that (evidently) just executing<\/b> the cursor will fetch the first row...<\/p>\n
\r\nPARSING IN CURSOR #1 len=15 dep=0 uid=95 oct=3 lid=95 tim=1234892785998349 hv=1134051363 ad='aacc6000'\r\nselect * from t\r\nEND OF STMT\r\nPARSE #1:c=0,e=638,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1234892785998346\r\nBINDS #1:\r\nEXEC #1:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1234892785998430\r\nWAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998461\r\nFETCH #1<\/B>:c=0,e=52,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=1234892785998541\r\nWAIT #1: nam='SQL*Net message from client' ela= 317 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998888\r\nSTAT #1 id=1 cnt=1 pid=0 pos=1 obj=258227 op='TABLE ACCESS FULL T (cr=7 pr=0 pw=0 time=37 us)'\r\nXCTEND rlbk=1, rd_only=1\r\nWAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998973\r\nWAIT #0: nam='SQL*Net message from client' ela= 152 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785999139\r\nXCTEND rlbk=0, rd_only=1\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"
I have noticed this over the past few months, and think I still may be missing something. Given the following code… #!\/home\/oracle\/local\/bin\/python import cx_Oracle import sys con = cx_Oracle.connect(“howards”,”******”,”perfrac”) con.cursor().execute(“alter session set events ‘10046 trace name context forever, level 12′”);…<\/p>\n
Read more →<\/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,24,22,26],"tags":[],"_links":{"self":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/633"}],"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=633"}],"version-history":[{"count":12,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/633\/revisions"}],"predecessor-version":[{"id":639,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/posts\/633\/revisions\/639"}],"wp:attachment":[{"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/media?parent=633"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/categories?post=633"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/appcrawler.com\/wordpress\/wp-json\/wp\/v2\/tags?post=633"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}