Hi all,
I am researching a change to speed up our application by reducing soft parsing. To do this I am caching SQL statements in our client code (implemented with OCCI). The results look promising - while most tests are unaffected, one particular test is down from 1100 seconds to 700 seconds. However there is something I dont understand - although the overall elapsed time for this test is reduced, the fetch elapsed time in the trace file is increased. Can anyone explain this? The overall benefit in elapsed time is seen in the reduction of SQL*Net message from client time, which should be the savings in the client processing the SQL statements and reduced network traffic.
First the results without the client cache. The same SQL is repeated about 900,000 times sequentially. This is an extreme scenario for one our use cases. (yes there may be better ways to code this, but...)
********************************************************************************
SELECT a,b,c,d,e,f,g,h
FROM MyTable WHERE d>=:1 AND d<:2 AND e=:3 AND f<=:4 AND f>:5
ORDER BY d,a
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 939379 11.62 10.27 0 0 0 0
Execute 939379 22.17 20.92 0 0 0 0
Fetch 946840 21.34 20.41 0 3157690 0 939380
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2825598 55.14 51.62 0 3157690 0 939380
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 946840 0.00 0.56
SQL*Net more data to client 59221 0.00 1.10
SQL*Net message from client 946840 0.03 260.17
Now the results with the statement cache. You can see the the parsing has been eliminated
********************************************************************************
SELECT a,b,c,d,e,f,g,h
FROM MyTable WHERE d>=:1 AND d<:2 AND e=:3 AND f<=:4 AND f>:5
ORDER BY d,a
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 939379 23.00 22.59 0 0 0 0
Fetch 946649 26.07 25.11 0 3157690 0 939380
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1886029 49.07 47.71 0 3157690 0 939380
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 953913 0.00 0.66
SQL*Net more data to client 58514 0.00 1.11
SQL*Net message from client 953913 0.25 190.93
The only explanation I can think of is that now Oracle is being asked to do the work much quicker than it was before, and that this somehow slows down the fetching. There is no extra wait event reported however. A smaller test with again shows increased fetch elapsed time but with reduced fetch CPU time.
Smaller test results without cache:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 33163 0.39 0.36 0 0 0 0
Execute 33163 1.31 0.88 0 0 0 0
Fetch 33433 0.75 0.73 0 106528 0 33162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 99759 2.45 1.98 0 106528 0 33162
...
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 33433 0.00 0.01
SQL*Net more data to client 1510 0.00 0.02
SQL*Net message from client 33433 0.01 9.54
With cache:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 33163 1.10 0.87 0 0 0 0
Fetch 33433 0.67 0.91 0 106528 0 33162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 66597 1.78 1.79 0 106528 0 33162
...
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 33433 0.00 0.02
SQL*Net more data to client 1422 0.00 0.02
SQL*Net message from client 33433 0.00 6.63
Notes. Testing was on 11.2.0.1 client against 10.2.0.1 server. All tracing was started and stopped automatically by client code, so there is no idle time in the traces. The test executes the SQL statements sequentially. The 4 CPU server was otherwise unused during the tests.
We had already previously enabled SESSION_CACHED_CURSORS on the server.