Skip to Main Content
  • Questions
  • 99% wait time on SQL*Net more data to client

Breadcrumb

May 4th

Question and Answer

Chris Saxon

Thanks for the question, Vepp.

Asked: January 21, 2020 - 2:58 pm UTC

Last updated: January 27, 2020 - 1:17 pm UTC

Version: 12c

Viewed 1000+ times

You Asked

Hello Team,

We are transferring 4 million records over the network and SQL*Net more data to client is 99%. We tried multiple drivers like ODBC, OLEDB , Oracle Drivers, QlikSense application Oracle drivers but the % didn't get reduced.

We have tested our network and 65K packet it took 0.687 millisecs. And overall its good as per n/w team.

The query completes in 33 secs and transfer takes 18 mins.

Please suggest a way to reduce the % of SQL*Net more data to client as Our N/w team and application team ran out of ideas.

I am sure, you guys might have come across multiple cases. Any pointers/area to look.

Below are the column data size

NVARCHAR2(36 CHAR)
NUMBER(38,0)
NVARCHAR2(36 CHAR)
NVARCHAR2(1000 CHAR)
NVARCHAR2(36 CHAR)
NVARCHAR2(255 CHAR)
NUMBER(1,0)
VARCHAR2(255 BYTE)
NVARCHAR2(100 CHAR)
NVARCHAR2(255 CHAR)
NVARCHAR2(1000 CHAR)


Thanks in advance.

and Chris said...

Check the array fetch size for your driver. This controls how many rows the client fetches on each request. The default for this is often low.

When this is set to a small value, most of the time is spent sending and receiving requests for the next batch of N rows.

For example, in SQL*Plus going fetching 1000 rows with

* arraysize 1 => over 30 seconds
* arraysize 1000 => under 1 second

create table t (
  c1 int
);

insert into t 
with rws as (
  select level x from dual
  connect by level <= 1000
)
  select x from rws;
  
commit;

select count(*) from t;

set timing on
set feed only
set arraysize 1

select /*arr 1*/* from t;

1000 rows selected.

Elapsed: 00:00:33.55

set arraysize 1000

select /*arr 1000*/* from t;

1000 rows selected.

Elapsed: 00:00:00.46

Rating

  (6 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

We did try the option

A reader, January 21, 2020 - 5:55 pm UTC

Thanks for the reply. We tried to play around array size but not much improvement. We tried maximum of 5000 and got only few mins difference.
Connor McDonald
January 22, 2020 - 2:58 am UTC

Can we see the complete trace data for the query, plus the DDL for the table.

By trace data, we mean

exec dbms_monitor.session_trace_enable(waits=>true)
run query
exec dbms_monitor.session_trace_disable

and show us the tkprof section pertaining to that query

on network waits.

Rajeshwaran, Jeyabal, January 22, 2020 - 1:02 am UTC

...
The query completes in 33 secs and transfer takes 18 mins.
...


If the query completes in 33 secs and network transfer took 18 min, why not use an approach like UTL_FILE to dump the contents on the server side - or perhaps have an mount path that is accessible on both server and client side and have a bit of PL/SQL to dump the contents of this table to that location - doing so we can have this wait "SQL*Net more data to client" reduced.

Trace Details & UNIX, Linux Compariosn

Vp, January 22, 2020 - 8:51 pm UTC

I got below details from DBAdmin and they told it is sufficient. The trace is generated while trying from a windows server 2016 machine

event waited on Times Waited Max Wait Total Waited
Lof File Sync 1 0 0
SQL*Net message to client 1631 0 0
SQL*Net message from client 1630 385.07 4044.61
Disk file Operations I/O 2 0 0
SQL*Net more data to client 197284 0.02 10.88
resmgr:cpu quantum 3 0 0

One more observation we found is interesting

We tried in Linux machine in same data center with SQL Plus 12.1 and the results came in 6 mins and we tried in 3 windows machines in same data center it took 18+ mins. So we all concluded, something is happening when we pull data from Linux oracle to Windows Sql plus.

will there be any difference when pulling data into Windows SQL Plus from Oracle Linux DB?

Linux Oracle to Linux Sqlplus is much faster. This is just our observation.




Connor McDonald
January 23, 2020 - 5:09 am UTC

The first thing I see in your output is that "more data to client" was only 10 seconds...The dominant part was the "from client" being 4000 seconds!

So I'm not sure I'm confident in using those figures.

Anyway, lets *assume* that "more data" was the issue here.

You'll can take a look at the raw trace file to get more info. For example, I copied your example

SQL> CREATE TABLE t (
  2      "ID"              NVARCHAR2(36)         NOT NULL ENABLE,
  3      "ROWINDEX"        NUMBER(*,0)         NOT NULL ENABLE,
  4      "UPLOADID"        NVARCHAR2(36)         NOT NULL ENABLE,
  5      "BUSINESSKEY"     NVARCHAR2(1000)         NOT NULL ENABLE,
  6      "BATCHID"         NVARCHAR2(36),
  7      "SERVICENAME"     NVARCHAR2(255)        NOT NULL ENABLE,
  8      "ISFAILED"        NUMBER(1,0)        NOT NULL ENABLE,
  9      "FAILREASON"      VARCHAR2(255 BYTE),
 10      "NAME"            NVARCHAR2(100)        NOT NULL ENABLE,
 11      "ATTRIBUTENAME"   NVARCHAR2(255),
 12      "ACTUALVALUE"     NVARCHAR2(1000)
 13  ) tablespace largets;

Table created.

SQL>
SQL> insert into t
  2  select
  3    sys_guid(),
  4    1,
  5    dbms_random.string('a',30),
  6    dbms_random.string('a',900),
  7    dbms_random.string('a',30),
  8    dbms_random.string('a',230),
  9    1,
 10    dbms_random.string('a',230),
 11    dbms_random.string('a',80),
 12    dbms_random.string('a',230),
 13    dbms_random.string('a',930)
 14  from dual
 15  connect by level <= 10000;

10000 rows created.

SQL>
SQL> insert into t
  2  select * from t;

10000 rows created.

SQL>
SQL> insert into t
  2  select * from t;

20000 rows created.

SQL>
SQL> commit;

Commit complete.

SQL>
SQL> exec dbms_stats.gather_table_stats('','T')

PL/SQL procedure successfully completed.

SQL> select num_rows, blocks , avg_row_len from user_tables
  2  where table_name = 'T';

  NUM_ROWS     BLOCKS AVG_ROW_LEN
---------- ---------- -----------
     40000      40697        5169


and then ran a simple SELECT *

The summarised trace data looks like:

select * 
from
 t


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch      401      0.84       1.68      31796      40210          0       40000
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      403      0.84       1.68      31796      40210          0       40000

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 104  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
     40000      40000      40000  TABLE ACCESS FULL T (cr=40210 pr=31796 pw=0 time=786007 us starts=1 cost=11036 size=206760000 card=40000)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                     401        0.00          0.00
  SQL*Net more data to client                 25599        0.00          0.35
  SQL*Net message from client                   401        0.00          0.05
  db file sequential read                       155        0.00          0.02
  db file scattered read                       1400        0.00          0.75
********************************************************************************



so you can see the ~25000 "more data" requests. To see how that came about, we can look at the raw trace data:

WAIT #2815597664216: nam='SQL*Net more data to client' ela= 15 driver id=1413697536 #bytes=8461 p3=0 obj#=7 tim=624936000635
WAIT #2815597664216: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=7142 p3=0 obj#=7 tim=624936000667
WAIT #2815597664216: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8461 p3=0 obj#=7 tim=624936000697
WAIT #2815597664216: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=7142 p3=0 obj#=7 tim=624936000729
WAIT #2815597664216: nam='SQL*Net more data to client' ela= 14 driver id=1413697536 #bytes=8461 p3=0 obj#=7 tim=624936000758
WAIT #2815597664216: nam='SQL*Net more data to client' ela= 13 driver id=1413697536 #bytes=7672 p3=0 obj#=7 tim=624936000789



Notice that on my setup, I'm capped at approx 8k per request.

Since I've 40000 rows at about 5169 bytes each, that is going to be:

40000 * 5169 / 8500 = ~25k requests.

So a couple of things:

a) Check out the SDU/TDU parmaeters in sqlnet.ora to bump up the request size
b) Remember that nvarchar2 is going to be twice the size as a varchar2. You can see from above, I only inserted approx 2600 characters per row, but this yields double that because of nvarchar2.

DDL

Vp, January 22, 2020 - 8:53 pm UTC

CREATE TABLE "A_100_TEST"."DQ_TEST_PERFORM1" (
    "ID"              NVARCHAR2(36)
        NOT NULL ENABLE,
    "ROWINDEX"        NUMBER(*,0)
        NOT NULL ENABLE,
    "UPLOADID"        NVARCHAR2(36)
        NOT NULL ENABLE,
    "BUSINESSKEY"     NVARCHAR2(1000)
        NOT NULL ENABLE,
    "BATCHID"         NVARCHAR2(36),
    "SERVICENAME"     NVARCHAR2(255)
        NOT NULL ENABLE,
    "ISFAILED"        NUMBER(1,0)
        NOT NULL ENABLE,
    "FAILREASON"      VARCHAR2(255 BYTE),
    "NAME"            NVARCHAR2(100)
        NOT NULL ENABLE,
    "ATTRIBUTENAME"   NVARCHAR2(255),
    "ACTUALVALUE"     NVARCHAR2(1000)
)
SEGMENT CREATION IMMEDIATE
PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255 NOCOMPRESS LOGGING
    STORAGE ( INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645 PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1 BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT
CELL_FLASH_CACHE DEFAULT )
TABLESPACE "TEST3";

What about virus scanning?

pmdba, January 23, 2020 - 2:15 pm UTC

If the main wait time is "from client", that would imply that your SQL*Net client is taking a long time to notify the database that it is ready for more data, not that data is taking a long time to arrive over the network once requested. Something is slowing down its overall processing. You noted the difference between Windows and Linux clients - are you running a virus scanner on the Windows system, and if so is it actively scanning running programs? That could have a serious impact on performance. If you are able to, temporarily disable any virus software running on the client and see if that makes a difference.
Chris Saxon
January 23, 2020 - 5:28 pm UTC

Good suggestion.

Finally its SQL trace

A reader, January 23, 2020 - 8:36 pm UTC

Thanks all for your responses.

All the wait for due to writing trace file.

TRACE_LEVEL_CLIENT was USER and TRACE_LEVEL_SERVER was user.

The moment we changed TRACE_LEVEL_CLIENT to 0, TRACE_LEVEL_SERVER=0 all the wait time gone and results came in 4 mins in windows environment.

Simple but took a lot of efforts to find out.
Chris Saxon
January 27, 2020 - 1:17 pm UTC

Doh!

Glad you got this sorted - thanks for letting us know how you resolved this. I'm sure this will come in handy for others in the future

More to Explore

Administration

Need more information on Administration? Check out the Administrators guide for the Oracle Database