Why would one queery hav 20x more sql*net message from client[idel] than other almost idenditcal query

From: mistton <sdfds_at_dsfds.com>
Date: 1 Mar 2007 08:35:04 -0600
Message-ID: <Xns98E65707423Dsdfs@216.40.28.86>

Running Oracle Version: 9.2.0.3.0 on Solaris 8 and Sun E15 10 CPU server.  

have client app from vendor (JAVA applet on IE 6) that runs an Oracle process at user request. The process is taking 20 minutes to run which is totally unacceptable  

Client is just sending commands to do stuff on database it does virtually no more work than that. (on client box its at 0% almost 99% of the time). once Oracle is finished it displays results by reading final results table.  

looked at what oracle is doing and found that CPU, I/O, reads etc taking up only 2 minutes rest is almost all idle time.  

PROBLEM:
One statement (almost identical to many others) is taking up 50% of SQL NET idle time, and it spends 95% of its total time in it. The statement is reading 1 row from a 1 row table holding currency info for USA, all varchar2 or date.

is it possible that say client does 10 queires problem one being last one then does work than talks to Oracle again and the idle time is added to this query?    

Did extended event tracing.  

here is Session Flat Profile :
Found Total SQL Statements: 730 (699 user statements, 31 internal statements)  

Note that SQL*Net message from client [idle] = 71.1%  

Event                                           % Time   Seconds  Calls - 

Time per Call - Avg Min Max
SQL*Net message from client [idle] 71.1% 845.1453s 193,429 0.0043s 0.0002s 144.0487s
unaccounted-for time 11.3% 134.5177s SQL*Net message from client 8.8% 104.7639s 87,046 0.0012s 0.0002s 5.1978s
EXEC calls [CPU] 4.2% 49.4900s 88,576 0.0005s -0.0300s 2.8500s FETCH calls [CPU] 2.7% 32.5700s 88,020 0.0003s 0.0000s 1.5000s PARSE calls [CPU] 1.1% 12.9100s 82,072 0.0001s -0.0100s 0.1300s db file sequential read 0.6% 7.6449s 2,452 0.0031s 0.0000s 0.1114s SQL*Net message to client 0.0% 0.7370s 280,476 0.0000s 0.0000s 0.0161s
SQL*Net more data to client 0.0% 0.2933s 3,899 0.0000s 0.0000s 0.0004s
db file scattered read 0.0% 0.2846s 88 0.0032s 0.0004s 0.0384s log file switch completion 0.0% 0.1399s 9 0.0155s 0.0000s 0.0407s SQL*Net more data from client 0.0% 0.0768s 880 0.0000s 0.0000s 0.0007s
log file sync 0.0% 0.0006s 1 0.0006s 0.0006s 0.0006s Total 100.0% 1,188.5742s    

Ok, SQL*NET is taking alot of time. well looking deeper i found that one statement is taking up 50% of it and it spends 95% of its time in it. the statement is reading 1 row from a 1 row table hold currency info for USA.  

Top 5 Statements per Event
SQL*Net message from client [idle]
SQL Statement Id % Time Seconds Calls - Time per Call - Avg Min Max

978251952  48.8%  412.2861s  26,840  0.0153s  0.0002s  0.4931s  
Cursor #0  23.9%  201.8160s  91  2.2178s  0.0003s  144.0487s  
3672891858  3.5%  29.1940s  26,850  0.0010s  0.0002s  0.3531s  
 
 

Statement Flat Profile for 978251952
FETCH calls [CPU] 0.5% 2.0200s 8,950 0.0002s 0.0 Avg Min Max
SQL*Net message from client [idle] 95.6% 412.2861s 26,840 0.0153s 0.0002s 0.4931s
SQL*Net message from client 3.2% 13.6379s 8,950 0.0015s 0.0003s 0.2314s
FETCH calls [CPU] 0.5% 2.0200s 8,950 0.0002s 0.0000s 0.0100s PARSE calls [CPU] 0.4% 1.6800s 8,950 0.0001s 0.0000s 0.0100s EXEC calls [CPU] 0.3% 1.4300s 8,950 0.0001s 0.0000s 0.0100s SQL*Net message to client 0.0% 0.1358s 44,730 0.0000s 0.0000s 0.0064s db file sequential read 0.0% 0.0169s 1 0.0169s 0.0169s 0.0169s Total 100.0% 431.2067s    

i found almost identical statements that are consumming much less of SQL Net time. they were done same amount of times etc  

for example
bad one  

select currencyid, currencycode, caption, ratecaption, scalefactor,   decimalplaces, lastuser, lastedited
from currency_country
order by currencycode  

Statement Cumulative Statistics
Call Cache
Misses Count - Seconds - Physical
Reads - Logical Reads - Rows
CPU Elapsed Consistent Current
Parse 1 8,950 1.6800s 2.0592s 0 0 0 0 Exec 0 8,950 1.4300s 1.7247s 0 0 0 0 Fetch 8,950 2.0200s 2.3454s 1 17,900 0 8,950 Total 1 26,850 5.1300s 6.1293s 1 17,900 0 8,950    

good one
select departmentid from bucket where bucketid = :v0  

Statement Cumulative Statistics
Call Cache
Misses Count - Seconds - Physical
Reads - Logical Reads - Rows
CPU Elapsed Consistent Current
Parse 1 12,059 0.7000s 1.3558s 0 0 0 0 Exec 0 12,059 0.6200s 2.9514s 0 0 0 0 Fetch 12,059 2.0700s 1.6046s 0 36,177 0 12,059 Total 1 36,177 3.3900s 5.9118s 0 36,177 0 12,059    

what is happening? is it totally how the client is working is ther nothing at the Oracle end? Received on Thu Mar 01 2007 - 08:35:04 CST