{"id":16,"date":"2022-11-24T22:15:23","date_gmt":"2022-11-24T21:15:23","guid":{"rendered":"http:\/\/cbleile.de\/wordpress\/?p=16"},"modified":"2023-02-05T22:16:50","modified_gmt":"2023-02-05T21:16:50","slug":"latency-test-from-client-to-oracle-db-minimum-number-of-rows-fetched-in-sqlplus-and-sqlcl","status":"publish","type":"post","link":"http:\/\/cbleile.de\/wordpress\/latency-test-from-client-to-oracle-db-minimum-number-of-rows-fetched-in-sqlplus-and-sqlcl\/","title":{"rendered":"Latency test from Client to Oracle DB: Minimum number of rows fetched in sqlplus and sqlcl"},"content":{"rendered":"\n

Some time ago I wrote a Blog<\/a> on how to calculate the network latency fetching a row to a Client from an Oracle database. The tool I used was sqlcl, because it just requires Java and hence no Oracle Client needs to be installed. Some people executed the script provided in the blog with sqlplus (also because current versions of sqlcl require Java 11) and saw only 1669 network round trips with 5000 rows and an arraysize of 1:<\/p>\n\n\n\n

test_netlat@orclcdb1@PDB1> exec dbms_output.put_line(to_char(:roundtrips_end - :roundtrips_begin)||' network round trips.');\n1669 network round trips.<\/strong>\n\ntest_netlat@orclcdb1@PDB1> exec dbms_output.put_line(to_char((:time_end - :time_begin)*10)||' ms elapsed time.');\n790 ms elapsed time.\n\ntest_netlat@orclcdb1@PDB1> exec dbms_output.put_line(to_char((:db_time_end - :db_time_start)\/1000)||' ms DB time.');\n165.841 ms DB time.\n\ntest_netlat@orclcdb1@PDB1> exec dbms_output.put_line(to_char(round((((:time_end - :time_begin)*10)-((:db_time_end - :db_time_start)\/1000))\/(:roundtrips_end - :roundtrips_begin),3))||' ms latency per round trip.');\n.374 ms latency per round trip.\n\ntest_netlat@orclcdb1@PDB1> exec dbms_output.put_line('--> (Elapsed Time - DB Time) \/ network round trips');\n--> (Elapsed Time - DB Time) \/ network round trips\n<\/code><\/pre>\n\n\n\n
REMARK: rowprefetch was set to the default of 1 during the sqlplus tests.<\/p>\n\n\n\n
With sqlcl I can see a number of network round trips closer to the expected 5000:<\/p>\n\n\n\n
SQL> exec dbms_output.put_line(to_char(:roundtrips_end - :roundtrips_begin)||' network round trips.');\n4953 network round trips.<\/strong>\n\nSQL> exec dbms_output.put_line(to_char((:time_end - :time_begin)*10)||' ms elapsed time.');\n2340 ms elapsed time.\n\nSQL> exec dbms_output.put_line(to_char((:db_time_end - :db_time_start)\/1000)||' ms DB time.');\n987.403 ms DB time.\n\nSQL> exec dbms_output.put_line(to_char(round((((:time_end - :time_begin)*10)-((:db_time_end - :db_time_start)\/1000))\/(:roundtrips_end - :roundtrips_begin),3))||' ms latency per round trip.');\n.273 ms latency per round trip.\n\nSQL> exec dbms_output.put_line('--> (Elapsed Time - DB Time) \/ network round trips');\n--> (Elapsed Time - DB Time) \/ network round trips\n<\/code><\/pre>\n\n\n\n
So how can we explain the 1669 network round trips with sqlplus and the 4953 network round trips with sqlcl?<\/p>\n\n\n\n
The number of rows fetched can be checked with sql_trace:<\/p>\n\n\n\n
set feed only\nalter session set sql_trace=true;\nselect filler from tlat ;\nalter session set sql_trace=false;\nset feed on<\/code><\/pre>\n\n\n\n
The trace file shows the following lines when running this with a 19.16. sqlplus against a 19.16-database:<\/p>\n\n\n\n
FETCH #139731510199544:c=67,e=66,p=0,cr=3,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=20585748787\nFETCH #139731510199544:c=9,e=9,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=20585749126\nFETCH #139731510199544:c=7,e=7,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=20585749293\nFETCH #139731510199544:c=8,e=8,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=20585749521\nFETCH #139731510199544:c=8,e=8,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=20585749706\nFETCH #139731510199544:c=0,e=8,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=20585749874\n...\n<\/code><\/pre>\n\n\n\n
Important is the information „r=“. The first fetch fetched 2 rows and all subsequent fetches fetched 3 rows.<\/p>\n\n\n\n
With sqlcl (version 22.3.1.0) I can see 50 rows fetched on the first fetch and then the expected 1 row fetched at a time:<\/p>\n\n\n\n
FETCH #140181223387392:c=52,e=52,p=0,cr=3,cu=0,mis=0,r=50<\/strong>,dep=0,og=1,plh=3090445234,tim=5975977699\nFETCH #140181223387392:c=17,e=17,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=5975978365\nFETCH #140181223387392:c=0,e=19,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=5975978679\nFETCH #140181223387392:c=0,e=13,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=5975978968\nFETCH #140181223387392:c=13,e=13,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=5975979473\nFETCH #140181223387392:c=13,e=13,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=5975979909\n...\n<\/code><\/pre>\n\n\n\n
So sqlplus in 19c has a minimum fetchsize (arraysize) of 3 except for the first fetch and sqlcl fetches the expected 1 row except for the first fetch, which takes 50 rows.<\/p>\n\n\n\n
REMARK: In earlier releases of sqlplus the minimum for arraysize was 2 with a first fetch of 1 row. E.g. in 12.1.0.2 or 12.2.0.1:<\/p>\n\n\n\n
FETCH #139833692592448:c=0,e=60,p=0,cr=4,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=422087587\nFETCH #139833692592448:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=422088651\nFETCH #139833692592448:c=0,e=16,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=422089371\nFETCH #139833692592448:c=0,e=15,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=422090092\n<\/code><\/pre>\n\n\n\n
In 18c it changed:<\/p>\n\n\n\n
FETCH #140635627289560:c=62,e=61,p=0,cr=3,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=559611770\nFETCH #140635627289560:c=22,e=22,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=559612282\nFETCH #140635627289560:c=15,e=14,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=559612368\nFETCH #140635627289560:c=34,e=34,p=0,cr=1,cu=0,mis=0,r=3<\/strong>,dep=0,og=1,plh=3090445234,tim=559612583\n<\/code><\/pre>\n\n\n\n
The old behavior up to 12.2. is documented in MOS Note
Pipelined Function with Pipe Row() Pipes out 15 Rows at a Time (Doc ID 1265916.1<\/a>):<\/p>\n\n\n\n
\n
SQL*Plus is written in OCI, and OCI has a default prefetch value of 1 row.<\/p>\n\n\n\n
The first fetch is 1 row, as 1 row is prefetched on the execute.
Then it either performs a scalar fetch, so one requested row plus one prefetched row,
or it performs an array fetch so you see eg :<\/p>\n\n\n\n
arraysize = 1, fetches are: 1, 2, 2, \u2026<\/p>\n\n\n\n
On the initial execute it fetches one row. So on the first fetch call SQLPlus makes it returns that row. On the second fetch call SQL<\/em>Plus makes, asking for one row, it has to go to
the database. This means it fetches the row requested plus it prefetches one additional row,
and you see two fetched. The next fetch call SQL*Plus makes uses the prefetched row,
then the next goes to the database and fetches two more and so on.<\/p>\n<\/blockquote>\n\n\n\n
So up to 12.2. sqlplus just relied on OCI’s prefetch-mechanism and hence the minimum fetch size was 2. Why do we see a minimum of 3 rows fetched from 18c onwards?<\/p>\n\n\n\n
I made a test with an OCI-program I took from MOS Note
OCI: Sample Program That Prefetches Rows (Doc ID 1126015.1<\/a>)<\/p>\n\n\n\n
The provided c-program was adjusted to use<\/p>\n\n\n\n
MAX_FETCH_COUNT 1 –> fetchsize, i.e. arraysize in sqlplus
prefetch_cnt = 1 –> prefetch-size of OCI<\/p>\n\n\n\n
The trace file running the program in 19c looks as follows:<\/p>\n\n\n\n
FETCH #139759481436136:c=115,e=115,p=0,cr=3,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=17304993374\nFETCH #139759481436136:c=0,e=50,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=17304993696\nFETCH #139759481436136:c=0,e=73,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=17304994078\nFETCH #139759481436136:c=41,e=41,p=0,cr=1,cu=0,mis=0,r=2<\/strong>,dep=0,og=1,plh=3090445234,tim=17304994447\n<\/code><\/pre>\n\n\n\n
After changing prefetch_cnt = 0 I really can see only 1 row per fetch:<\/p>\n\n\n\n
FETCH #140542285248488:c=93,e=93,p=0,cr=3,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=17507201670\nFETCH #140542285248488:c=74,e=74,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=17507202044\nFETCH #140542285248488:c=47,e=46,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=17507202294\nFETCH #140542285248488:c=28,e=28,p=0,cr=1,cu=0,mis=0,r=1<\/strong>,dep=0,og=1,plh=3090445234,tim=17507202563\n<\/code><\/pre>\n\n\n\n
From the tests it’s not clear what caused the behavior change in 18c. The new features described in the release notes of sqlplus in 18c<\/a> seem not related.  <\/p>\n\n\n\n
Summary: The script provided in Blog Script to calculate the network latency between the application and the Oracle DB-server<\/a> is correct, but you may consider that sqlplus and sqlcl provide a different number of fetches (with arraysize 1), i.e. the amount of data transported may be bit different, but that should not have any impact on the result. To be 100% correct with the latency an OCI-program can be used with a fetchsize of 1 and a prefetch-size of 0. Alternatively you may test with an arraysize of 3 in sqlplus and sqlcl.<\/p>\n","protected":false},"excerpt":{"rendered":"
Some time ago I wrote a Blog on how to calculate the network latency fetching a row to a Client from an Oracle database. The tool I used was sqlcl, because it just requires Java and hence no Oracle Client needs to be installed. Some people executed the script provided in the blog with sqlplus […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[9],"tags":[16,3],"class_list":["post-16","post","type-post","status-publish","format-standard","hentry","category-oracle","tag-latency","tag-oracle"],"_links":{"self":[{"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/posts\/16","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/comments?post=16"}],"version-history":[{"count":1,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/posts\/16\/revisions"}],"predecessor-version":[{"id":17,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/posts\/16\/revisions\/17"}],"wp:attachment":[{"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/media?parent=16"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/categories?post=16"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/cbleile.de\/wordpress\/wp-json\/wp\/v2\/tags?post=16"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}