Re: XML queries and Excessive Network Traffic
- From: Jared Still <jkstill@xxxxxxxxx>
- To: Oracle-L Freelists <oracle-l@xxxxxxxxxxxxx>
- Date: Mon, 3 Nov 2014 10:47:16 -0800
On Fri, Jul 18, 2014 at 2:03 PM, Jared Still <jkstill@xxxxxxxxx> wrote:
> This week I have run into an interesting issue that causes some pretty
> slow queries on XML data.
>
> The problem is not the speed at which oracle returns the data - the
> problem is the amount of sqlnet traffic being generated.
>
The solution to this problem seems to be this: use the 12.1 OCI (Thick)
client.
The problem encountered has been classified as a bug by Oracle.
Here's my tests.
The client has reported good results in following this.
*Summary:*
- installed 12.1 instant file (checked all boxes)
- also have 11.2.0.1 client
- ran tests for the following against XML table
- 11.2 thin
- 12.1 thin
- 12.1 thick (OCI) no prefetch
- 12.1 thick (OCI) with prefetch via oraaccess.xml
The test table is small at 76 rows, with XMLData elements of up to a few K.
Method-R mrskew results are shown in the trace files.
What is interesting to see is that when the thick (OCI) client is used
there are no calls to 'SQL*Net more data to client'
This corresponds to much lower FETCH times in the OCI connected sessions.
Recommendation
Download and install SQL Developer 4.0.3
http://www.oracle.com/technetwork/developer-tools/sql-developer/overview/index.html
Install an 11.2.0.3+ or 12.1 Instant Client
I've not tested the 11.2.0.3 thick client, and at this time recommend using
the 12.1 Instant Client
http://www.oracle.com/technetwork/database/features/instant-client/index-097480.html
Follow the instructions for OCI setup in the new SQL Developer version:
http://www.thatjeffsmith.com/archive/2014/01/oracle-sql-developer-4-and-the-oracle-client/
Use the 'Test' button to verify all is OK
OCI test success
SQL Developer 4.0.3 OCI test for 12.1 ORACLE_HOME
Testing the Oracle Home located at C:\Oracle\product\12.1.0\client
Testing client directory ... OK
Testing loading Oracle JDBC driver ... OK
Testing checking Oracle JDBC driver version ... OK
Driver version: 12.1.0.2.0
Testing testing native OCI library load ... OK
Success!
OCI test fail
SQL Developer 4.0.3 OCI test for 11.2 ORACLE_HOME
Testing the Oracle Home located at C:\Oracle\product\11gR2
Testing client directory ... OK
Testing loading Oracle JDBC driver ... OK
Testing checking Oracle JDBC driver version ... Failed:
Minimum driver version 11.2.0.3 required, specified driver version is
11.2.0.1.0
*Details:*
xmltest.sql
alter system flush buffer_cache;
alter system flush buffer_cache;
alter system flush buffer_cache;
alter session set tracefile_identifier='XMLDATA';
select value tracefile from v$diag_info where name = 'Default Trace File';
-- when using SQL Developer oradebug must be run from sqlplus sessoin
-- oradebug setmypid
-- oradebug event 10079 trace name context forever, level 2
alter session set events '10046 trace name context forever, level 12';
select filename, xmltype.getclobval(xmldata) xmldata
from XMLTEST.xmltest_2
order by filename;
select value tracefile from v$diag_info where name = 'Default Trace File';
XML test results using xmltest.sql
Note the thick client does not have any 'more data to client' calls, and
corresponding lower FETCH times.
##################################################
sqldev4-11g-trace/js02_ora_23040_XMLDATA.trc
CALL-NAME DURATION % CALLS MEAN
MIN MAX
SQL*Net message from client 14.449065 97.9% 7 2.064152
0.000683 6.988251
FETCH 0.149000 1.0% 4 0.037250
0.000000 0.147000
db file sequential read 0.090325 0.6% 24 0.003764
0.000256 0.012311
direct path read 0.050408 0.3% 64 0.000788
0.000023 0.008257
db file scattered read 0.015897 0.1% 7 0.002271
0.000418 0.007978
SQL*Net more data to client 0.006851 0.0% 47 0.000146
0.000098 0.000303
ADR block file read 0.002515 0.0% 2 0.001257
0.000303 0.002212
EXEC 0.001000 0.0% 4 0.000250
0.000000 0.001000
SQL*Net message to client 0.000124 0.0% 7 0.000018
0.000003 0.000105
Disk file operations I/O 0.000010 0.0% 1 0.000010
0.000010 0.000010
PARSE 0.000000 0.0% 4 0.000000
0.000000 0.000000
CLOSE 0.000000 0.0% 8 0.000000
0.000000 0.000000
XCTEND 0.000000 0.0% 1 0.000000
0.000000 0.000000
TOTAL (13) 14.765195 100.0% 180 0.082029
0.000000 6.988251
================
RANGE {min ? e < max} DURATION % CALLS MEAN MIN MAX
1. 0ms 5ms 0.003225 0.0% 3 0.001075 0.000683 0.001693
2. 5ms 10ms
3. 10ms 15ms
4. 15ms 20ms
5. 20ms 25ms
6. 25ms 50ms
7. 50ms 100ms
8. 100ms 1,000ms 1.043862 7.2% 2 0.521931 0.135264 0.908598
9. 1,000ms +INF 13.401978 92.8% 2 6.700989 6.413727 6.988251
TOTAL (9) 14.449065 100.0% 7 2.064152 0.000683 6.988251
##################################################
sqldev4-12c-thick-trace-noprefetch/js02_ora_25733_XMLDATA.trc
CALL-NAME DURATION % CALLS MEAN
MIN MAX
SQL*Net message from client 21.530814 99.4% 95 0.226640
0.000518 6.259186
db file sequential read 0.036993 0.2% 5 0.007399
0.003345 0.014182
FETCH 0.033000 0.2% 6 0.005500
0.000000 0.031000
direct path read 0.017883 0.1% 19 0.000941
0.000173 0.004878
db file scattered read 0.013696 0.1% 7 0.001957
0.000469 0.005970
LOBREAD 0.011000 0.1% 87 0.000126
0.000000 0.001000
ADR block file read 0.010380 0.0% 2 0.005190
0.000331 0.010049
SQL*Net message to client 0.001648 0.0% 95 0.000017
0.000002 0.000188
EXEC 0.001000 0.0% 6 0.000167
0.000000 0.001000
Disk file operations I/O 0.000009 0.0% 1 0.000009
0.000009 0.000009
PARSE 0.000000 0.0% 6 0.000000
0.000000 0.000000
CLOSE 0.000000 0.0% 10 0.000000
0.000000 0.000000
XCTEND 0.000000 0.0% 1 0.000000
0.000000 0.000000
TOTAL (13) 21.656423 100.0% 340 0.063695
0.000000 6.259186
================
RANGE {min ? e < max} DURATION % CALLS MEAN MIN MAX
1. 0ms 5ms 0.079380 0.4% 87 0.000912 0.000518 0.002710
2. 5ms 10ms
3. 10ms 15ms
4. 15ms 20ms 0.017776 0.1% 1 0.017776 0.017776 0.017776
5. 20ms 25ms 0.023027 0.1% 1 0.023027 0.023027 0.023027
6. 25ms 50ms 0.027455 0.1% 1 0.027455 0.027455 0.027455
7. 50ms 100ms
8. 100ms 1,000ms
9. 1,000ms +INF 21.383176 99.3% 5 4.276635 1.405902 6.259186
TOTAL (9) 21.530814 100.0% 95 0.226640 0.000518 6.259186
##################################################
sqldev4-12c-thick-trace-prefetch/js02_ora_26239_XMLDATA.trc
CALL-NAME DURATION % CALLS MEAN
MIN MAX
SQL*Net message from client 11.653988 99.1% 92 0.126674
0.000588 7.805141
FETCH 0.028000 0.2% 4 0.007000
0.000000 0.028000
db file sequential read 0.022801 0.2% 5 0.004560
0.000345 0.009121
direct path read 0.018508 0.2% 19 0.000974
0.000248 0.005276
db file scattered read 0.016997 0.1% 7 0.002428
0.000528 0.007529
LOBREAD 0.016000 0.1% 87 0.000184
0.000000 0.001000
EXEC 0.001000 0.0% 4 0.000250
0.000000 0.001000
SQL*Net message to client 0.000527 0.0% 92 0.000006
0.000002 0.000071
Disk file operations I/O 0.000006 0.0% 1 0.000006
0.000006 0.000006
PARSE 0.000000 0.0% 4 0.000000
0.000000 0.000000
CLOSE 0.000000 0.0% 8 0.000000
0.000000 0.000000
XCTEND 0.000000 0.0% 1 0.000000
0.000000 0.000000
TOTAL (12) 11.757827 100.0% 324 0.036290
0.000000 7.805141
================
RANGE {min ? e < max} DURATION % CALLS MEAN MIN MAX
1. 0ms 5ms 0.095472 0.8% 87 0.001097 0.000588 0.003448
2. 5ms 10ms
3. 10ms 15ms 0.013354 0.1% 1 0.013354 0.013354 0.013354
4. 15ms 20ms
5. 20ms 25ms
6. 25ms 50ms
7. 50ms 100ms 0.055473 0.5% 1 0.055473 0.055473 0.055473
8. 100ms 1,000ms 0.800728 6.9% 1 0.800728 0.800728 0.800728
9. 1,000ms +INF 10.688961 91.7% 2 5.344480 2.883820 7.805141
TOTAL (9) 11.653988 100.0% 92 0.126674 0.000588 7.805141
##################################################
sqldev4-12c-thin-trace-noprefetch/js02_ora_23654_XMLDATA.trc
CALL-NAME DURATION % CALLS MEAN
MIN MAX
SQL*Net message from client 22.136379 98.9% 8 2.767047
0.001548 8.095962
FETCH 0.145000 0.6% 4 0.036250
0.000000 0.143000
direct path read 0.044818 0.2% 64 0.000700
0.000142 0.010429
db file scattered read 0.019328 0.1% 7 0.002761
0.000456 0.008408
db file sequential read 0.018072 0.1% 5 0.003614
0.000349 0.006442
ADR block file read 0.008414 0.0% 2 0.004207
0.000375 0.008039
SQL*Net more data to client 0.007740 0.0% 47 0.000165
0.000104 0.000242
PARSE 0.001000 0.0% 4 0.000250
0.000000 0.001000
SQL*Net message to client 0.000025 0.0% 8 0.000003
0.000003 0.000004
Disk file operations I/O 0.000007 0.0% 1 0.000007
0.000007 0.000007
CLOSE 0.000000 0.0% 8 0.000000
0.000000 0.000000
EXEC 0.000000 0.0% 4 0.000000
0.000000 0.000000
XCTEND 0.000000 0.0% 1 0.000000
0.000000 0.000000
TOTAL (13) 22.380783 100.0% 163 0.137305
0.000000 8.095962
================
RANGE {min ? e < max} DURATION % CALLS MEAN MIN MAX
1. 0ms 5ms 0.009530 0.0% 4 0.002383 0.001548 0.004259
2. 5ms 10ms
3. 10ms 15ms
4. 15ms 20ms
5. 20ms 25ms
6. 25ms 50ms
7. 50ms 100ms
8. 100ms 1,000ms 0.835370 3.8% 1 0.835370 0.835370 0.835370
9. 1,000ms +INF 21.291479 96.2% 3 7.097160 5.116909 8.095962
TOTAL (9) 22.136379 100.0% 8 2.767047 0.001548 8.095962
Jared Still
Certifiable Oracle DBA and Part Time Perl Evangelist
Principal Consultant at Pythian
Pythian Blog http://www.pythian.com/blog/author/still/
Oracle Blog: http://jkstill.blogspot.com
Home Page: http://jaredstill.com
Other related posts:
