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 (also because current versions of sqlcl require Java 11) and saw only 1669 network round trips with 5000 rows and an arraysize of 1:

[email protected]@PDB1> exec dbms_output.put_line(to_char(:roundtrips_end - :roundtrips_begin)||' network round trips.');
1669 network round trips.

[email protected]@PDB1> exec dbms_output.put_line(to_char((:time_end - :time_begin)*10)||' ms elapsed time.');
790 ms elapsed time.

[email protected]@PDB1> exec dbms_output.put_line(to_char((:db_time_end - :db_time_start)/1000)||' ms DB time.');
165.841 ms DB time.

[email protected]@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.');
.374 ms latency per round trip.

[email protected]@PDB1> exec dbms_output.put_line('--> (Elapsed Time - DB Time) / network round trips');
--> (Elapsed Time - DB Time) / network round trips

REMARK: rowprefetch was set to the default of 1 during the sqlplus tests.

With sqlcl I can see a number of network round trips closer to the expected 5000:

SQL> exec dbms_output.put_line(to_char(:roundtrips_end - :roundtrips_begin)||' network round trips.');
4953 network round trips.

SQL> exec dbms_output.put_line(to_char((:time_end - :time_begin)*10)||' ms elapsed time.');
2340 ms elapsed time.

SQL> exec dbms_output.put_line(to_char((:db_time_end - :db_time_start)/1000)||' ms DB time.');
987.403 ms DB time.

SQL> 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.');
.273 ms latency per round trip.

SQL> exec dbms_output.put_line('--> (Elapsed Time - DB Time) / network round trips');
--> (Elapsed Time - DB Time) / network round trips

So how can we explain the 1669 network round trips with sqlplus and the 4953 network round trips with sqlcl?

The number of rows fetched can be checked with sql_trace:

set feed only
alter session set sql_trace=true;
select filler from tlat ;
alter session set sql_trace=false;
set feed on

The trace file shows the following lines when running this with a 19.16. sqlplus against a 19.16-database:

FETCH #139731510199544:c=67,e=66,p=0,cr=3,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=20585748787
FETCH #139731510199544:c=9,e=9,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=20585749126
FETCH #139731510199544:c=7,e=7,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=20585749293
FETCH #139731510199544:c=8,e=8,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=20585749521
FETCH #139731510199544:c=8,e=8,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=20585749706
FETCH #139731510199544:c=0,e=8,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=20585749874
...

Important is the information “r=”. The first fetch fetched 2 rows and all subsequent fetches fetched 3 rows.

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:

FETCH #140181223387392:c=52,e=52,p=0,cr=3,cu=0,mis=0,r=50,dep=0,og=1,plh=3090445234,tim=5975977699
FETCH #140181223387392:c=17,e=17,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=5975978365
FETCH #140181223387392:c=0,e=19,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=5975978679
FETCH #140181223387392:c=0,e=13,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=5975978968
FETCH #140181223387392:c=13,e=13,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=5975979473
FETCH #140181223387392:c=13,e=13,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=5975979909
...

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.

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:

FETCH #139833692592448:c=0,e=60,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=422087587
FETCH #139833692592448:c=0,e=23,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=422088651
FETCH #139833692592448:c=0,e=16,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=422089371
FETCH #139833692592448:c=0,e=15,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=422090092

In 18c it changed:

FETCH #140635627289560:c=62,e=61,p=0,cr=3,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=559611770
FETCH #140635627289560:c=22,e=22,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=559612282
FETCH #140635627289560:c=15,e=14,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=559612368
FETCH #140635627289560:c=34,e=34,p=0,cr=1,cu=0,mis=0,r=3,dep=0,og=1,plh=3090445234,tim=559612583

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):

SQL*Plus is written in OCI, and OCI has a default prefetch value of 1 row.

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 :

arraysize = 1, fetches are: 1, 2, 2, …

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 SQLPlus 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.

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?

I made a test with an OCI-program I took from MOS Note
OCI: Sample Program That Prefetches Rows (Doc ID 1126015.1)

The provided c-program was adjusted to use

MAX_FETCH_COUNT 1 –> fetchsize, i.e. arraysize in sqlplus
prefetch_cnt = 1 –> prefetch-size of OCI

The trace file running the program in 19c looks as follows:

FETCH #139759481436136:c=115,e=115,p=0,cr=3,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=17304993374
FETCH #139759481436136:c=0,e=50,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=17304993696
FETCH #139759481436136:c=0,e=73,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=17304994078
FETCH #139759481436136:c=41,e=41,p=0,cr=1,cu=0,mis=0,r=2,dep=0,og=1,plh=3090445234,tim=17304994447

After changing prefetch_cnt = 0 I really can see only 1 row per fetch:

FETCH #140542285248488:c=93,e=93,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=17507201670
FETCH #140542285248488:c=74,e=74,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=17507202044
FETCH #140542285248488:c=47,e=46,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=17507202294
FETCH #140542285248488:c=28,e=28,p=0,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3090445234,tim=17507202563

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 seem not related.

Summary: The script provided in Blog Script to calculate the network latency between the application and the Oracle DB-server 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.