why would 1 query take 20X more SQL*Net message from client[idel] time than almost identical quieres -
03-01-2007
, 07:03 AM
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
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? |