Full Frontal PR: Getting People Talking about You, Your Business, or Your Product
ISBN: 1590595254
EAN: 2147483647
EAN: 2147483647
Year: 2005
Pages: 41
Pages: 41
Authors: Richard Laermer, Michael Prichinello
The profiler is a long awaited (by me anyway) feature. It provides us with a source code profiler for our PL/SQL applications. In the past, you would tune your PL/SQL applications using SQL_TRACE and TKPROF. This would help you identify and tune your long running SQL, but trying to discover where the bottlenecks in 5,000 lines of PL/SQL code are (which you might not have even written yourself) was pretty near impossible. You typically ended up instrumenting the code with lots of calls to DBMS_UTILITY.GET_TIME to measure elapsed time, in an attempt to find out what was slow.
Well, you no longer have to do this - we have the DBMS_PROFILER package. I am going to demonstrate how I use it. I myself use little of its total functionality - I just use it to find the really bad areas, and go straight there. I use it in a very simplistic fashion. It is set up and designed to do much more than presented here, however.
The statistics gathering takes place in database tables. These tables are set up to hold the statistics for many different runs of the code. This is OK for some people, but I like to just keep the last run or two, in there only. Any more than that and it gets too confusing. Sometimes, too much information is just that - too much information.
Your DBA may have to install the profiler in your database. The procedure for installing this package is simple:
cd [ORACLE_HOME]/rdbms/admin.
using SVRMGRL you would connect as SYS or INTERNAL.
Run profload.sql.
In order to actually use the profiler after that, you will need to have the profiling tables installed. You can install these once per database, but I recommend that developers have their own copy. Fortunately, the DBMS_PROFILER package is built with invoker rights and unqualified table names, so that we can install the tables in each schema, and the profiler package will use them correctly. The reason you each want your own tables, is so that you only see the results of your profiling runs, not those of your co-workers. In order to get a copy of the profiling tables in your schema, you would run [ORACLE_HOME]\rdbms\admin\proftab.sql in SQL*PLUS. After you run proftab.sql, you'll need to run profrep.sql as well. This script creates views and packages to operate on the profiler tables in order to generate reports. This script is found in [ORACLE_HOME]\plsql\demo\profrep.sql. You should run this in your schema as well, after creating the tables.
I like to keep a small script around to reset these tables, and clear them out every so often. After I've done a run or two and have analyzed the results, I run this script. I have the following in a script I call profreset.sql:
-- uses deletes because of foreign key constraints delete from plsql_profiler_data; delete from plsql_profiler_units; delete from plsql_profiler_runs;
Now we are ready to start profiling. I'm going to demonstrate the use of this package by running two different implementations of a factorial algorithm. One is recursive, and the other is iterative. We'll use the profiler to see which one is faster, and what components of the code are 'slow' in each implementation. The test driver for this is simply:
tkyte@TKYTE816> @profreset tkyte@TKYTE816> create or replace 2 function fact_recursive( n int ) return number 3 as 4 begin 5 if ( n = 1 ) 6 then 7 return 1; 8 else 9 return n * fact_recursive(n-1); 10 end if; 11 end; 12 / Function created. tkyte@TKYTE816> create or replace 2 function fact_iterative( n int ) return number 3 as 4 l_result number default 1; 5 begin 6 for i in 2 .. n 7 loop 8 l_result := l_result * i; 9 end loop; 10 return l_result; 11 end; 12 / Function created. tkyte@TKYTE816> set serveroutput on tkyte@TKYTE816> exec dbms_profiler.start_profiler( 'factorial recursive' ) PL/SQL procedure successfully completed. tkyte@TKYTE816> begin 2 for i in 1 .. 50 loop 3 dbms_output.put_line( fact_recursive(50) ); 4 end loop; 5 end; 6 / 30414093201713378043612608166064768844300000000000000000000000000 ... 30414093201713378043612608166064768844300000000000000000000000000 PL/SQL procedure successfully completed. tkyte@TKYTE816> exec dbms_profiler.stop_profiler PL/SQL procedure successfully completed. tkyte@TKYTE816> exec dbms_profiler.start_profiler( 'factorial iterative' ) PL/SQL procedure successfully completed. tkyte@TKYTE816> begin 2 for i in 1 .. 50 loop 3 dbms_output.put_line( fact_iterative(50) ); 4 end loop; 5 end; 6 / 30414093201713378043612608166064768844300000000000000000000000000 ... 30414093201713378043612608166064768844300000000000000000000000000 PL/SQL procedure successfully completed. tkyte@TKYTE816> exec dbms_profiler.stop_profiler PL/SQL procedure successfully completed.
In order to collect statistics for a profiler run, we must call START_PROFILER. We name each run with some meaningful name, and then start running the code. I ran the factorial routines 50 times each before ending the statistics collection for a given run. Now, we are ready to analyze the results.
In [ORACLE_HOME]/plsql/demo there is a script profsum.sql. Don't run it- some of the queries in that script can take a considerable amount of time to execute (could take hours), and the amount of data it produces is very large. Below is the modified profsum.sql I use myself. It provides much of the same information, but the queries execute quickly, and many of the really detailed reports are cut out. Also, some of the queries would include the timings for the STOP_PROFILER call in it, and others would not, skewing the observations from query to query. I've adjusted all of the queries to not include the timings of the profiler package itself.
My profsum.sql is the following, and this of course is available for download at htpp://http://www.apress.com/
set echo off set linesize 5000 set trimspool on set serveroutput on set termout off column owner format a11 column unit_name format a14 column text format a21 word_wrapped column runid format 9999 column secs format 999.99 column hsecs format 999.99 column grand_total format 9999.99 column run_comment format a11 word_wrapped column line# format 99999 column pct format 999.9 column unit_owner format a11 spool profsum.out /* Clean out rollup results, and recreate. */ update plsql_profiler_units set total_time = 0; execute prof_report_utilities.rollup_all_runs; prompt = prompt = prompt ==================== prompt Total time select grand_total/1000000000 as grand_total from plsql_profiler_grand_total; prompt = prompt = prompt ==================== prompt Total time spent on each run select runid, substr(run_comment,1, 30) as run_comment, run_total_time/1000000000 as secs from (select a.runid, sum(a.total_time) run_total_time, b.run_comment from plsql_profiler_units a, plsql_profiler_runs b where a.runid = b.runid group by a.runid, b.run_comment ) where run_total_time > 0 order by runid asc; prompt = prompt = prompt ==================== prompt Percentage of time in each module, for each run separately select p1.runid, substr(p2.run_comment, 1, 20) as run_comment, p1.unit_owner, decode(p1.unit_name, '', '<anonymous>', substr(p1.unit_name,1, 20)) as unit_name, p1.total_time/1000000000 as secs, TO_CHAR(100*p1.total_time/p2.run_total_time, '999.9') as percentage from plsql_profiler_units p1, (select a.runid, sum(a.total_time) run_total_time, b.run_comment from plsql_profiler_units a, plsql_profiler_runs b where a.runid = b.runid group by a.runid, b.run_comment ) p2 where p1.runid=p2.runid and p1.total_time > 0 and p2.run_total_time > 0 and (p1.total_time/p2.run_total_time) >= .01 order by p1.runid asc, p1.total_time desc; column secs form 9.99 prompt = prompt = prompt ==================== prompt Percentage of time in each module, summarized across runs select p1.unit_owner, decode(p1.unit_name, '', '<anonymous>', substr(p1.unit_name,1, 25)) as unit_name, p1.total_time/1000000000 as secs, TO_CHAR(100*p1.total_time/p2.grand_total, '99999.99') as percentage from plsql_profiler_units_cross_run p1, plsql_profiler_grand_total p2 order by p1.total_time DESC; prompt = prompt = prompt ==================== prompt Lines taking more than 1% of the total time, each run separate select p1.runid as runid, p1.total_time/10000000 as Hsecs, p1.total_time/p4.grand_total*100 as pct, substr(p2.unit_owner, 1, 20) as owner, decode(p2.unit_name, '', '<anonymous>', substr(p2.unit_name,1, 20)) as unit_name, p1.line#, ( select p3.text from all_source p3 where p3.owner = p2.unit_owner and p3.line = p1.line# and p3.name=p2.unit_name and p3.type not in ( 'PACKAGE', 'TYPE' )) text from plsql_profiler_data p1, plsql_profiler_units p2, plsql_profiler_grand_total p4 where (p1.total_time >= p4.grand_total/100) AND p1.runID = p2.runid and p2.unit_number=p1.unit_number order by p1.total_time desc; prompt = prompt = prompt ==================== prompt Most popular lines (more than 1%), summarize across all runs select p1.total_time/10000000 as hsecs, p1.total_time/p4.grand_total*100 as pct, substr(p1.unit_owner, 1, 20) as unit_owner, decode(p1.unit_name, '', '<anonymous>', substr(p1.unit_name,1, 20)) as unit_name, p1.line#, ( select p3.text from all_source p3 where (p3.line = p1.line#) and (p3.owner = p1.unit_owner) AND (p3.name = p1.unit_name) and (p3.type not in ( 'PACKAGE', 'TYPE' ) ) ) text from plsql_profiler_lines_cross_run p1, plsql_profiler_grand_total p4 where (p1.total_time >= p4.grand_total/100) order by p1.total_time desc; execute prof_report_utilities.rollup_all_runs; prompt = prompt = prompt ==================== prompt Number of lines actually executed in different units (by unit_name) select p1.unit_owner, p1.unit_name, count( decode( p1.total_occur, 0, null, 0)) as lines_executed , count(p1.line#) as lines_present, count( decode( p1.total_occur, 0, null, 0))/count(p1.line#) *100 as pct from plsql_profiler_lines_cross_run p1 where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY', 'PROCEDURE', 'FUNCTION' ) ) group by p1.unit_owner, p1.unit_name; prompt = prompt = prompt ==================== prompt Number of lines actually executed for all units select count(p1.line#) as lines_executed from plsql_profiler_lines_cross_run p1 where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY', 'PROCEDURE', 'FUNCTION' ) ) AND p1.total_occur > 0; prompt = prompt = prompt ==================== prompt Total number of lines in all units select count(p1.line#) as lines_present from plsql_profiler_lines_cross_run p1 where (p1.unit_type in ( 'PACKAGE BODY', 'TYPE BODY', 'PROCEDURE', 'FUNCTION' ) ); spool off set termout on edit profsum.out set linesize 131
I have gone out of my way to make that report fit into an 80-column screen, you could be more generous with some of the column formats if you don't use Telnet frequently.
Now, let's look at the output of our factorial run, the results of running the above profsum.sql script:
Total time GRAND_TOTAL ----------- 5.57
This tells us the grand total of our run times across both runs was 5.57 seconds. Next, we'll see a breakdown by run:
Total time spent on each run RUNID RUN_COMMENT SECS ----- ----------- ------- 17 factorial 3.26 recursive 18 factorial 2.31 iterative
This shows us already that the recursive routine is not nearly as efficient as the iterative version, it took almost 50 percent longer to execute. Next, we will look at the amount of time spent in each module (package or procedure) in both runs, and the raw percentage of time by run:
Percentage of time in each module, for each run separately RUNID RUN_COMMENT UNIT_OWNER UNIT_NAME SECS PERCEN ----- ----------- ----------- -------------- ------- ------ 17 factorial TKYTE FACT_RECURSIVE 1.87 57.5 recursive 17 factorial SYS DBMS_OUTPUT 1.20 36.9 recursive 17 factorial <anonymous> <anonymous> .08 2.5 recursive 17 factorial <anonymous> <anonymous> .06 1.9 recursive 18 factorial SYS DBMS_OUTPUT 1.24 53.6 iterative 18 factorial TKYTE FACT_ITERATIVE .89 38.5 iterative 18 factorial <anonymous> <anonymous> .08 3.4 iterative 18 factorial <anonymous> <anonymous> .06 2.7 iterative 8 rows selected.
In this example, we see that in the recursive implementation, 57 percent of our run-time is spent in our routine, 37 percent in DBMS_OUTPUT, and the rest in miscellaneous routines. In our second run, the percentages are quite different. Our code is only 38 percent of the total run-time, and that it 38 percent of a smaller number! This already shows that the second implementation is superior to the first. More telling is the SECS column. Here, we can see that the recursive routine took 1.87 seconds, whereas the iterative routine took only .89. If we ignore DBMS_OUTPUT for a moment, we see that the iterative routine is two times faster than the recursive implementation.
It should be noted that you might not get exactly the same percentages (or even close) on your system. If you do not have SERVEROUTPUT ON in SQL*PLUS for example, DBMS_OUTPUT might not even show up on your system. If you run on a slower or faster machine, the numbers will be very different. For example, when I ran this on my Sparc Solaris machine, the GRAND_TOTAL time was about 1.0 seconds, and the percentages spent in each section of code were slightly different. Overall, the end result was much the same, percentage-wise.
Now we can look at the time spent in each module summarized across the runs. This will tell us what piece of code we spend most of our time in:
Percentage of time in each module, summarized across runs UNIT_OWNER UNIT_NAME SECS PERCENTAG ----------- -------------- ----- --------- SYS DBMS_OUTPUT 2.44 43.82 TKYTE FACT_RECURSIVE 1.87 33.61 TKYTE FACT_ITERATIVE .89 16.00 <anonymous> <anonymous> .33 5.88 SYS DBMS_PROFILER .04 .69
Here, is it obvious we could cut our run-time almost in half by removing the single call to DBMS_OUTPUT. In fact, if you simply SET SERVEROUTPUT OFF, effectively disabling DBMS_OUTPUT, and rerun the test, you should find that it drops down to 3 percent or less of the total run-time. Currently however, it is taking the largest amount of time. What is more interesting than this, is that 33 percent of the total time is in the recursive routine and only 16 percent in the iterative - the iterative routine is much faster.
Now, let's look at some more details:
Lines taking more than 1% of the total time, each run separate RUNID HSECS PCT OWNER UNIT_NAME LINE TEXT ----- ------- ------ ----- -------------- ---- --------------------- 17 142.47 25.6 TKYTE FACT_RECURSIVE 8 return n*fact_recursive(n-1); 18 68.00 12.2 TKYTE FACT_ITERATIVE 7 l_result := l_result * i; 17 43.29 7.8 TKYTE FACT_RECURSIVE 4 if ( n = 1 ) 17 19.58 3.5 SYS DBMS_OUTPUT 116 a3 a0 51 a5 1c 6e 81 b0 18 19.29 3.5 TKYTE FACT_ITERATIVE 5 for i in 2 .. n 18 17.66 3.2 SYS DBMS_OUTPUT 116 a3 a0 51 a5 1c 6e 81 b0 17 14.76 2.7 SYS DBMS_OUTPUT 118 1c 51 81 b0 a3 a0 1c 51 18 14.49 2.6 SYS DBMS_OUTPUT 118 1c 51 81 b0 a3 a0 1c 51 18 13.41 2.4 SYS DBMS_OUTPUT 142 :2 a0 a5 b b4 2e d b7 19 17 13.22 2.4 SYS DBMS_OUTPUT 142 :2 a0 a5 b b4 2e d b7 19 18 10.62 1.9 SYS DBMS_OUTPUT 166 6e b4 2e d :2 a0 7e 51 b4 17 10.46 1.9 SYS DBMS_OUTPUT 166 6e b4 2e d :2 a0 7e 51 b4 17 8.11 1.5 SYS DBMS_OUTPUT 72 1TO_CHAR: 18 8.09 1.5 SYS DBMS_OUTPUT 144 8f a0 b0 3d b4 55 6a :3 a0 18 8.02 1.4 SYS DBMS_OUTPUT 72 1TO_CHAR: 17 8.00 1.4 SYS DBMS_OUTPUT 144 8f a0 b0 3d b4 55 6a :3 a0 17 7.52 1.4 <ano> <anonymous> 3 18 7.22 1.3 <ano> <anonymous> 3 18 6.65 1.2 SYS DBMS_OUTPUT 141 a0 b0 3d b4 55 6a :3 a0 7e 18 6.21 1.1 <ano> <anonymous> 1 17 6.13 1.1 <ano> <anonymous> 1 18 5.77 1.0 SYS DBMS_OUTPUT 81 1ORU-10028:: line length 22 rows selected.
Here, I am printing out the run-time in hundreds of seconds instead of seconds, and showing the percentages as well. No surprises here - we would expect that line 8 in the recursive routine and line 7 in the iterative routine would be the big ones. Here, we can see that they are. This part of the report gives you specific lines in the code to zero in on and fix. Notice the strange looking lines of code from DBMS_OUTPUT. This is what wrapped PL/SQL looks like in the database. It is just a bytecode representation of the actual source, designed to obscure it from prying eyes like yours and mine.
Now, the next report is similar to the one above, but it aggregates results across runs, whereas the numbers above show percentages within a run:
Most popular lines (more than 1%), summarize across all runs HSECS PCT OWNER UNIT_NAME LINE TEXT ------- ------ ----- -------------- ---- --------------------- 142.47 25.6 TKYTE FACT_RECURSIVE 8 return n * fact_recursive(n-1); 68.00 12.2 TKYTE FACT_ITERATIVE 7 l_result := l_result * i; 43.29 7.8 TKYTE FACT_RECURSIVE 4 if ( n = 1 ) 37.24 6.7 SYS DBMS_OUTPUT 116 a3 a0 51 a5 1c 6e 81 b0 29.26 5.3 SYS DBMS_OUTPUT 118 1c 51 81 b0 a3 a0 1c 51 26.63 4.8 SYS DBMS_OUTPUT 142 :2 a0 a5 b b4 2e d b7 19 21.08 3.8 SYS DBMS_OUTPUT 166 6e b4 2e d :2 a0 7e 51 b4 19.29 3.5 TKYTE FACT_ITERATIVE 5 for i in 2 .. n 16.88 3.0 <ano> <anonymous> 1 16.13 2.9 SYS DBMS_OUTPUT 72 1TO_CHAR: 16.09 2.9 SYS DBMS_OUTPUT 144 8f a0 b0 3d b4 55 6a :3 a0 14.74 2.6 <ano> <anonymous> 3 11.28 2.0 SYS DBMS_OUTPUT 81 1ORU-10028:: line length overflow, 10.17 1.8 SYS DBMS_OUTPUT 147 4f 9a 8f a0 b0 3d b4 55 9.52 1.7 SYS DBMS_OUTPUT 73 1DATE: 8.54 1.5 SYS DBMS_OUTPUT 117 a3 a0 1c 51 81 b0 a3 a0 7.36 1.3 SYS DBMS_OUTPUT 141 a0 b0 3d b4 55 6a :3 a0 7e 6.25 1.1 SYS DBMS_OUTPUT 96 1WHILE: 6.19 1.1 SYS DBMS_OUTPUT 65 1499: 5.77 1.0 SYS DBMS_OUTPUT 145 7e a0 b4 2e d a0 57 b3 20 rows selected.
Lastly, we'll take a look at some of the code coverage statistics. This is useful not only for profiling and performance tuning, but testing as well. This tells you how many of the statements in the code we have executed, and shows the percentage of the code that has been 'covered':
Number of lines actually executed in different units (by unit_name) UNIT_OWNER UNIT_NAME LINES_EXECUTED LINES_PRESENT PCT ----------- -------------- -------------- ------------- ------ SYS DBMS_OUTPUT 51 88 58.0 SYS DBMS_PROFILER 9 62 14.5 TKYTE FACT_ITERATIVE 4 4 100.0 TKYTE FACT_RECURSIVE 3 3 100.0 = = ==================== Number of lines actually executed for all units LINES_EXECUTED -------------- 67 = = ==================== Total number of lines in all units LINES_PRESENT ------------- 157
This shows that of the 88 statements in the DBMS_OUTPUT package, we executed 51 of them. It is interesting to note how DBMS_PROFILER counts lines or statements here. It claims that FACT_ITERATIVE has 4 lines of code, but if we look at the source code:
function fact_iterative( n int ) return number as l_result number default 1; begin for i in 2 .. n loop l_result := l_result * i; end loop; return l_result; end;
I don't see four of anything clearly. DBMS_PROFILER is counting statements, and not really lines of code. Here, the four statements are:
... l_result number default 1; ... for i in 2 .. n ... l_result := l_result * i; ... return l_result; ...
Everything else, while necessary to compile and execute the code, was not really executable code, and therefore, not statements. DBMS_PROFILER can be used to tell us how many executable statements we have in our code, and how many of them we actually executed.
The only caveats I have with regards to DBMS_PROFILER, are the amount of data it generates, and the amount of your time it can consume.
The small test case we did above generated some 500-plus rows of observations in the PLSQL_PROFILER_DATA table. This table contains eleven number columns, and so it is not very 'wide', but it grows rapidly. Every statement executed will cause a row to be added to this table. You will need to monitor the space you need for this table, and make sure you clear it out every now and again. Typically, this is not a serious issue, but I have seen this table getting filled with thousands of rows for extremely complex PL/SQL routines (hundreds of thousands of rows).
The amount of your time it can consume, is a more insidious problem. No matter how much you tune, there will always be a line of code that consumes the most amount of time. If you remove this line of code from the top of the list, another one is just waiting to take its place. You will never get a report from DBMS_PROFILER that says, 'everything ran so fast, I won't even generate a report.' In order to use this tool effectively, you have to set some goals for yourself - give yourself a finish line. Either set a time boundary (I will tune this routine to the best of my ability for two hours), or a performance metric boundary (when the run-time is N units long, I will stop). Otherwise, you will find yourself (as I have from time to time) spending an inordinate amount of time fine-tuning a routine that just cannot get any faster.
DBMS_PROFILER is a nice tool with lots of detailed information. It is far too easy to get bogged down in the details.
In this section we have covered the uses of the DBMS_PROFILER package. One of its two main uses is source code profiling to detect where in the code time is being spent, or to compare two different algorithms. The other major use is as a code coverage tool, to report back the percentage of executable statements your test routines actually exercised in the application. While 100 percent code coverage does not assure you of bug free code - it certainly brings you a step closer though.
We also developed a report, based on the example profiler report provided by Oracle. This report extracts the basic information you need in order to use the DBMS_PROFILER tool successfully. It avoids the great detail you can go into, providing you with the aggregate view of what happened in your application, and more details on the most expensive parts. It may be the only report you really need to use with this tool in order to identify bottlenecks and tune your application.