In a previous post,  I pointed out that SQL*Net message from client is not always an idle wait from the user’s point of view.

During a performance investigation, I traced the application that wasn’t performing to expectations.  Here is an excerpt from a trace file:

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1145      0.12       0.13          0          0          0           0
Execute   1145      0.28       0.33          2          7         37           4
Fetch     1645      0.46       0.52          0       4314          0        5242
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     3935      0.86       0.99          2       4321         37        5246

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
 Event waited on                             Times   Max. Wait  Total Waited
 ----------------------------------------   Waited  ----------  ------------
 SQL*Net message to client                    5197        0.00          0.02
 SQL*Net message from client                  5197        0.90         58.88
 SQL*Net more data to client                   516        0.00          0.05
 SQL*Net more data from client                  40        0.00          0.00
 direct path read                               28        0.00          0.02
 db file sequential read                         2        0.01          0.02
 log file sync                                   4        0.00          0.01

Most of the response time from the application/user’s point of view ocurred “outside” of the database.  What was surprising, was that so many round trips were required for what seems like a simple function of the application, and that the tkprof report doesn’t show the waits associated with a cursor.

Looking at the trace file, the SQL*Net round trips always followed certain SQL statements:

PARSING IN CURSOR #1 len=120 dep=0 uid=53 oct=3 lid=53 tim=19783142399235 hv=1095791004 ad='906c6620'
SELECT * FROM TABLE_A WHERE COL1=:a AND COL2=:b
END OF STMT
PARSE #1:c=0,e=195,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=19783142399223
EXEC #1:c=0,e=271,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=19783142399755
WAIT #1: nam='SQL*Net message to client' ela= 4 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142399974
WAIT #1: nam='SQL*Net more data to client' ela= 93 driver id=1952673792 #bytes=2001 p3=0 obj#=72685 tim=19783142400471
FETCH #1:c=0,e=374,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=1,tim=19783142400540
WAIT #1: nam='SQL*Net message from client' ela= 13126 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142413820
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142413956
WAIT #0: nam='SQL*Net message from client' ela= 8580 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142422616
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142422836
WAIT #0: nam='SQL*Net message from client' ela= 12421 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142435416
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142435546
WAIT #0: nam='SQL*Net message from client' ela= 10679 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142446296
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142446409
WAIT #0: nam='SQL*Net message from client' ela= 10579 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142457049
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142457144
WAIT #0: nam='SQL*Net message from client' ela= 11231 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142468451
WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142468561
WAIT #0: nam='SQL*Net message from client' ela= 12782 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142481436
WAIT #0: nam='SQL*Net message to client' ela= 9 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142481763
WAIT #0: nam='SQL*Net message from client' ela= 7636 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142489618
WAIT #0: nam='SQL*Net message to client' ela= 3 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142489736
WAIT #0: nam='SQL*Net message from client' ela= 12990 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142502814
WAIT #0: nam='SQL*Net message to client' ela= 6 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142503127
WAIT #0: nam='SQL*Net message from client' ela= 10648 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142513875
WAIT #0: nam='SQL*Net message to client' ela= 2 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142514010
WAIT #0: nam='SQL*Net message from client' ela= 8445 driver id=1952673792 #bytes=1 p3=0 obj#=72685 tim=19783142522541

Notice the waits for cursor #0.  I guessed this was some sort of OCI call that happened after the rows for the cursor had been returned.  This seems to get used for low level work that isn’t associated directly to a user’s cursor.  When I examined TABLE_A I saw that it had several CLOBs and BLOBs in it.  Were they to blame for the high number of round trips?

I found some Metalink notes which explain what is going on:
Note:398380.1     Poor Performance When Using CLOBS and Oracle Net
Bug No. 3892362   CLOBS HAVE POOR NETWORK PERFORMANCE – REQUEST FOR PRODUCT ENHANCEMENT
Note:66431.1      LOBS – Storage, Redo and Performance Issues
Note:401589.1     Performance Problems Using Clob and Blobs
Bug:7341386

Basically, not only does having LOB columns in a select restrict each fetch to one row at a time, additional round trips are needed to handle LOB locators and to retrieve data from the LOBs.  This can cause performance problems with high latency networks because of the high number of round trips (over 5000 in our case).

However, in another Oracle note, it is said:

“If I write OCI code then I can define an array of OCILobLocators and use array fetch with this and you get multiple rows in each net packet. In summary I do not see any server bug here. Whether array fetch is used for CLOBs or not is up to the client code. “

From the manual http://download.oracle.com/docs/cd/B28359_01/appdev.111/b28395/oci07lob.htm :

Array Interface for LOBs
You can use the OCI array interface with LOBs, just as with any other datatype. There are two ways of using the array interface.
1.    Using the data interface

You can bind or define arrays of character data for a CLOB column or RAW data for a BLOB column. You can use array bind and define interfaces to insert and select multiple rows with LOBs in one round trip to the server…..”

In the example traced above, the problem ended up being with the configuration of the virtual application server, (okay, so not strictly LOB vs Network this time), but any communication latency can be multiplied by applications that access LOBs via many round trips as in the example above.  This is another LOB related performance issue that can be difficult to identify.  (See the first one I posted about).

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s