asked on

Analysing tkprof results from a web session?

I set up trace on a web application I'm working on. I manually refreshed the page five times, and got the following results that are included in the "code snippet" (the actual SQL (which is an "INSERT AS SELECT" executed through a database link into a temporary table after which more operations on the result set are performed) has been snipped):

I'm a bit baffled by the results.
1) Does this mean that the first time I ran this, a hard parse was done on the query, and the following refreshes were only soft parses?
2) Am I to expect (due to the stateless nature of web applications) that since this query is executed every time the report is generated, that the parses will always be this "high" compared to the executes?

The reason I'm asking these is that I'm a lot more used to seeing just a few parses compared to the number of executes/fetches in tkprof reports. Of course, normally I don't run the tool on web sessions, so I'm propably "out of my turf" on this one.

The system is Oracle 9.2.0.8 on Win32 platform accessed through Apache+mod_plsql.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        5      0.01       0.01          0          0          0           0
Execute      5      0.70       0.72          0      45388      10058        3560
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       10      0.71       0.73          0      45388      10058        3560
 
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 47     (recursive depth: 1)
 
Rows     Row Source Operation
-------  ---------------------------------------------------
    712  COUNT  
    712   VIEW  
    712    SORT ORDER BY 
    712     MERGE JOIN CARTESIAN 
    712      TABLE ACCESS BY INDEX ROWID APPLICATION 
    713       INDEX RANGE SCAN APPLICATIONS_SEARCH_GENERIC2 (object id 33223)
   2465        INDEX RANGE SCAN APPLICATION_VACANCY_IX (object id 33487)
      0        INDEX UNIQUE SCAN APPLICATION_VACANCY_LINK_PK (object id 30748)
    712      BUFFER SORT 
      1       TABLE ACCESS FULL DUAL 
 
 
Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to dblink                       3        0.00          0.00
  SQL*Net message from dblink                     3        0.00          0.00
********************************************************************************

Open in new window

ASKER CERTIFIED SOLUTION

Sean Stuber

membership

This solution is only available to members.

To access this solution, you must be a member of Experts Exchange.

Start Free Trial

DiscoNova

ASKER

Thank you. This was exactly what I wanted to hear.

Unfortunately, since we already have connection pooling enabled (this is Windows platform with multithreaded Apache, we're able to persist the temporary table contents between requests - of course, this means we've been forced to build a system that allows us to identify each session's contents in the temp tables as they are shared among all "sessions") I believe mod_plsql calls dbms_session.reset_package which causes this high amount of parsing to be done.

On the bright side; things could be worse. At least it's mostly soft parses the application is performing - I had just started the server, so that is why I experienced this one hard parse in my test. Under normal circumstances I'd expect the query to be always present in the library cache.