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'");
cursor = con.cursor()
cursor.arraysize = 1000
try:
cursor.execute("drop table t")
except:
pass
cursor.execute("create table t(c number)")
cursor.execute("insert into t select rownum from user_objects where rownum <= 5")
con.commit()
cursor.execute("select * from t")
for row in cursor.fetchall():
print row[0]
cursor.close()
con.close()
...which is then executed as follows...
emgrid01:oracle:emprod1:/home/oracle>./testFetch.py
1
2
3
4
5
emgrid01:oracle:emprod1:/home/oracle>vi testFetch.py
...I get the following the resulting trace file...
PARSING IN CURSOR #1 len=15 dep=0 uid=95 oct=3 lid=95 tim=1234892270413286 hv=1134051363 ad='aeab5dd8'
select * from t
END OF STMT
PARSE #1:c=0,e=686,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1234892270413282
BINDS #1:
EXEC #1:c=0,e=41,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1234892270413373
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413404
FETCH #1:c=0,e=50,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1234892270413507
WAIT #1: nam='SQL*Net message from client' ela= 323 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413862
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270413891
FETCH #1:c=0,e=34,p=0,cr=5,cu=0,mis=0,r=4,dep=0,og=4,tim=1234892270413918
WAIT #1: nam='SQL*Net message from client' ela= 316 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414281
STAT #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)'
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414363
WAIT #0: nam='SQL*Net message from client' ela= 152 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=1234892270414528
XCTEND rlbk=0, rd_only=1
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.
I then tried the code above, but commented out the for row in fetchall(): piece. I found that (evidently) just executing the cursor will fetch the first row...
PARSING IN CURSOR #1 len=15 dep=0 uid=95 oct=3 lid=95 tim=1234892785998349 hv=1134051363 ad='aacc6000'
select * from t
END OF STMT
PARSE #1:c=0,e=638,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1234892785998346
BINDS #1:
EXEC #1:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1234892785998430
WAIT #1: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998461
FETCH #1:c=0,e=52,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=1234892785998541
WAIT #1: nam='SQL*Net message from client' ela= 317 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998888
STAT #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)'
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785998973
WAIT #0: nam='SQL*Net message from client' ela= 152 driver id=1413697536 #bytes=1 p3=0 obj#=258226 tim=1234892785999139
XCTEND rlbk=0, rd_only=1