Method R Discussion GroupMethod R helps developers, DBAs, and decision-makers optimize Oracle-based software in every phase of the software life cycle. |
||
Discuss Method R products, techniques, and events. Ask new questions or post your own responses. |
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bi
PL/SQL Release 10.2.0.3.0 - Production on Solaris 8 Want to see if others have notices this issue: I have an anonymous block which basically generates a file via utl_file. The block was running slower than expected about 25 minutes. After troubleshooting I found if I commented out the utl_file.put_line block the time dropped to 6 minutes. To confirm I ran it through dbms_profiler. In profiler it placed a small value for the utl_file line. plsql_profiler_data.total_time was 18150080. The problem was the sum(total_time) for the runid did not equal the actual run time. There was about 25 minutes missing. After much searching around on metalink/net I found no reference to this issue. Finally I went to try a test like this: create table measure_utl_file( iteration number, start_ts timestamp(9), end_ts timestamp(9), duration_1 INTERVAL DAY(1) TO SECOND(9)); then in the code if v_buffer is not null then utl_file_writes := utl_file_writes + 1; sts := systimestamp; UTL_FILE.PUT_LINE(v_output_file,v_buffer); ets := systimestamp; insert into measure_utl_file(iteration,start_ts,end_ts,duration_1) values (utl_file_writes,sts,ets,(ets-sts)); end if; once the block was done running I did: select sum(extract(second from duration_1)) from measure_utl_file SUM(EXTRACT(SECONDFROMDURATION_1)) ---------------------------------- 1249.797178 but the total_time was 18150080 in profiler. Seems like I found the missing time. I will probably do another check using a 10046 trace once I get hold of a DBA. My question is: Is this expected behavior of the dbms_profiler or a bug? Thanks Pete Thanks Pete
Hi Pete,
If I understand your tests correctly it sounds like you see that the total R (response time as seen by you) and the time accounted for by DBMS_PROFILER are different. I haven't done as extensive testing as you have but I would suspect that this is expected. The DBMS_PROFILER is just profiling the "stuff" that happens with in a PL/SQL block. As we know there are several event that can happen while SQL or PL/SQL is running. File I/O and Network traffic to name just two of the likely big ones. Also there is time taken up to startup and shutdown the PL/SQL engine. These are not accounted for by DBMS_PROFILER so I would expect the total R to be greater then the time accounted for by DBMS_PROFILER. The intent of the profiler is to let you know what is happening within the PL/SQL block and it's not intended to tell you about the response time. The 10046 trace tell you that. I hope this helps. Ric |
Powered by FogBugz