I have a stored procedure that sometimes runs significantly slower than others. I have two different timers measuring the execution time at different scopes. One is in the client code, measuring only the OCI execute call. The second is inside the PL/SQL procedure itself, timing the inside of the procedure's main block.
Normally, if the procedure's timer takes, say, 5 seconds to run, the client's timer is only a few milliseconds greater. This is completely reasonable. The problem is that sometimes the client's timer will be much greater than the procedure's, even double.
I've eliminated any issue on the client or in the transport layer. I enabled client and server logging in sqlnet.ora at support level. On the client, the gap between request and response packets is essentially equal to the client code's timer. On the server, a similar gap is seen between the incoming request and the outgoing response.
The question remains, if the overall call takes 10 seconds, and inside the procedure takes only 5 seconds, where did the other 5 seconds go?
I don't expect the exact answer to the above question, but I would like to hear ideas on how to go about finding the answer. What logs can I turn on to give me insight into what Oracle is doing both after the request arrives but before the actual call to the procedure, and after the procedure until the response is sent back to the client?
Edit:
Perhaps there's something wrong with my timing methodology? I'm using dbms_utility.get_cpu_time() (which provides time in hundredths of a second, hence the division by 100.)
PROCEDURE foo (elapsed_time OUT NUMBER) IS
start_time NUMBER;
BEGIN
start_time := dbms_utility.get_cpu_time();
-- ... PL/SQL stuffs
elapsed_time := (dbms_utility.get_cpu_time() - start_time) / 100;
END;
