PL/SQL   Performance   Issues     
       
          System / Application PL/SQL Performance Issues  

 

 

 

Overview

 

In this article we’ll examine how to detect and monitor system and application-level PL/SQL performance issues using the three PL/SQL statistics held in the system and session time model tables.

 

 

PL/SQL Statistics

 

System-wide performance statistics are held in table “v$sys_time_model”, with columns:

 

*  stat_id

*  stat_name

*  value

 

Session specific performance statistics are held in table “v$sess_time_model”, with columns:

 

*  sid

*  stat_id

*  stat_name

*  value

 

Both tables hold the same set of statistics, but at different levels of granularity. The statistics that we are interested in here relate to PL/SQL, of which there are three:

 

*  PL/SQL Compilation Elapsed Time: defined by Oracle as the “Amount of elapsed time spent running the PL/SQL compiler.”

 

*  PL/SQL Execution Elapsed Time: defined by Oracle as the “Amount of elapsed time spent running the PL/SQL interpreter. This does not include time spent recursively executing/parsing SQL statements or time spent recursively executing the Java VM.”

 

*  Inbound PL/SQL RPC Elapsed Time: defined by Oracle as the “Time inbound PL/SQL remote procedure calls have spent executing. It includes all time spent recursively executing SQL and JAVA, and therefore is not easily related to ‘PL/SQL execution elapsed time’.”

 

In order to determine how much time these PL/SQL specific activities are contributing to the total database elapsed time, it’s useful to have a measure of what this total elapsed time might be, and this is provided by statistic:

 

*  DB Time: defined by Oracle as the “Amount of elapsed time (in microseconds) spent performing Database user-level calls. This does not include the time spent on instance background processes such as PMON.”

 

Expressing the PL/SQL statistics as percentages of “DB Time” provide convenient metrics for identifying issues and for monitoring changes in resource usage over time.

 

 

System PL/SQL Statistics

 

To determine the values of the PL/SQL statistics at the system level, across all database sessions, we can use the following SQL statement:


-- DISPLAY TOTAL DATABASE TIME, PL/SQL COMPILATION / EXECUTION TIMES, AND PERCENTAGES with -- GET TOTAL DATABASE TIME AND PL/SQL TIMES IN MICROSECONDS FOR ALL SESSIONS w_total_times as ( SELECT sum( decode( stat_name, 'DB time', value, 0 ) ) db_time, sum( decode( stat_name, 'PL/SQL compilation elapsed time', value, 0 ) ) pc_time, sum( decode( stat_name, 'PL/SQL execution elapsed time', value, 0 ) ) px_time, sum( decode( stat_name, 'inbound PL/SQL rpc elapsed time', value, 0 ) ) pi_time FROM v$sys_time_model WHERE stat_name in ( 'DB time', 'PL/SQL compilation elapsed time', 'PL/SQL execution elapsed time', 'inbound PL/SQL rpc elapsed time' ) ) -- CALCULATE PERCENTAGE PL/SQL TIMES AND FORMAT RESULTS ( SELECT rpad( 'Total Database Time:', 68 ) || to_char( round( db_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total PL/SQL Compilation Elapsed Time:', 68 ) || to_char( round( pc_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total PL/SQL Execution Elapsed Time:', 68 ) || to_char( round( px_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total Inbound PL/SQL RPC Elapsed Time:', 68 ) || to_char( round( pi_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total PL/SQL Compilation Time as Percentage of Total Database Time:', 73 ) || to_char( round( pc_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Execution Time as Percentage of Total Database Time:', 73 ) || to_char( round( px_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Inbound RPC Time as Percentage of Total Database Time:', 73 ) || to_char( round( pi_time * 100 / db_time, 2 ), '990.09' ) || ' %' all_sessions_plsql_stats FROM w_total_times );

Running this SQL query will produce results similar to the following:

 

Statistic NameValue
Total Database Time585,398,836 μs
Total PL/SQL Compilation Elapsed Time11,842,857 μs
Total PL/SQL Execution Elapsed Time178,283,596 μs
Total Inbound PL/SQL RPC Elapsed Time7,626,981 μs
Total PL/SQL Compilation Time as Percentage of Total Database Time2.02 %
Total PL/SQL Execution Time as Percentage of Total Database Time30.46 %
Total PL/SQL Inbound RPC Time as Percentage of Total Database Time1.30 %

 

 

Application PL/SQL Statistics

 

While looking at system wide statistics can be useful from a DBA perspective, from a developer perspective it’s more useful to look at PL/SQL performance issues in the context of a particular application (say, a few dozen PL/SQL packages and standalone procedures and functions). By running a particular application within the context of a session, and then examining the PL/SQL session statistics, we can often determine the PL/SQL performance characteristics for the application in question.

 

To determine the values of the PL/SQL statistics at the application level, in the context of the current database session, we can use the following SQL statement:


-- DISPLAY TOTAL CURRENT SESSION DATABASE TIME, PL/SQL COMPILATION / EXECUTION TIMES, AND PERCENTAGES with -- GET SID FOR CURRENT SESSION w_session_sid as ( SELECT sid FROM v$session WHERE audsid = userenv( 'sessionid' ) ), -- GET TOTAL DATABASE TIME AND PL/SQL TIMES IN MICROSECONDS FOR CURRENT SESSION w_total_times as ( SELECT sum( decode( stat_name, 'DB time', value, 0 ) ) db_time, sum( decode( stat_name, 'PL/SQL compilation elapsed time', value, 0 ) ) pc_time, sum( decode( stat_name, 'PL/SQL execution elapsed time', value, 0 ) ) px_time, sum( decode( stat_name, 'inbound PL/SQL rpc elapsed time', value, 0 ) ) pi_time FROM v$sess_time_model WHERE sid = ( select sid from w_session_sid ) AND stat_name in ( 'DB time', 'PL/SQL compilation elapsed time', 'PL/SQL execution elapsed time', 'inbound PL/SQL rpc elapsed time' ) ) -- CALCULATE PERCENTAGE PL/SQL TIMES AND FORMAT RESULTS ( SELECT rpad( 'Total Current Session Database Time:', 68 ) || to_char( round( db_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total Current Session PL/SQL Compilation Elapsed Time:', 68 ) || to_char( round( pc_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total Current Session PL/SQL Execution Elapsed Time:', 68 ) || to_char( round( px_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total Current Session Inbound PL/SQL RPC Elapsed Time:', 68 ) || to_char( round( pi_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total PL/SQL Compilation Time as Percentage of Total Database Time:', 73 ) || to_char( round( pc_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Execution Time as Percentage of Total Database Time:', 73 ) || to_char( round( px_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Inbound RPC Time as Percentage of Total Database Time:', 73 ) || to_char( round( pi_time * 100 / db_time, 2 ), '990.09' ) || ' %' current_session_plsql_stats FROM w_total_times );

However, there a big caveat here: the statistics in this session table are only reliable if we have a moderately heavy application load, and we discount various factors that can bias the results – as the following examples illustrate.

 

Database Startup

 

If we start up the database, open a new session (in SQL Plus), and run the statistics query we could get:

 

Statistic NameValue
Total Session Database Time465,719 μs
Total Session PL/SQL Compilation Elapsed Time114,749 μs
Total Session PL/SQL Execution Elapsed Time3,401 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

Now we might have expected that the PL/SQL statistics would be zero. However, even though we’ve neither explicitly compiled nor executed any PL/SQL within this session, the two main PL/SQL statistics have non zero values. If we rerun the SQL query within the same session, we’ll find that this “behind the scenes” PL/SQL activity does not reoccur, and the PL/SQL statistics do not change (though the “DB Time” statistic increases as we might reasonably expect).

 

If we close this session, open another, and then rerun the statistics query, then we get a very different set of results:

 

Statistic NameValue
Total Session Database Time3,230 μs
Total Session PL/SQL Compilation Elapsed Time0 μs
Total Session PL/SQL Execution Elapsed Time33 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

The overheads seem to be almost entirely restricted to the first session opened after the database has been started up. Subsequent sessions have zero values for all the PL/SQL statistics, apart from the elapsed execution time, which is typically around 100 μs. Normally, this subsequent PL/SQL activity is too small to impact PL/SQL performance monitoring, but if we’re looking at very small elapsed execution times, then we need to subtract it off any subsequent measurements that we make.

 

DDL Operations

 

Let’s close the current session, open a new session, get the statistics, create a table, and populate it with one row:


             CREATE TABLE plsql_test (
                col number
             );
             INSERT INTO plsql_test VALUES ( 1.11 );
      

Now let’s re-examine the statistics and calculate the changes that result from running the SQL code (in general, it’s good practice wait at least five seconds before generating the statistics to allow the internal memory structures to be updated):

 

Statistic NameValue
Total Session Database Time915,430 μs
Total Session PL/SQL Compilation Elapsed Time116,245 μs
Total Session PL/SQL Execution Elapsed Time7,608 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

Even though we’ve run SQL and not PL/SQL both the two main PL/SQL elapsed times have increased significantly. If we drop the table, close the session, open another session, and recreate the table and row as before, we get very different numbers:

 

Statistic NameValue
Total Session Database Time24,670 μs
Total Session PL/SQL Compilation Elapsed Time0 μs
Total Session PL/SQL Execution Elapsed Time984 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

If we repeat the process we will get similar figures on each repetition, as is also the case it we try a table with a different name. So it’s the first creation of a table following bringing up the database than has the most significant impact. However, the PL/SQL elapsed execution time still increases even on repetitions, and so could bias measurements if we mix SQL and PL/SQL together in the intervals between gathering statistics.

 

PL/SQL Compilation

 

Let’s close the current session, open a new session, get the statistics, and run the following PL/SQL code:


             CREATE PROCEDURE test_plsql AS
                v_x number;
                v_y number;
             BEGIN
                for inx in 1..1000 loop
                   select sum( sqrt( col ) ) into v_x from plsql_test;
                   for jnx in 1..1000 loop
                      v_y := dbms_random.value;
                   end loop;
                end loop;
             END;
      

and then re-examine the statistics and calculate the changes that result from running the PL/SQL code:

 

Statistic NameValue
Total Session Database Time35,901 μs
Total Session PL/SQL Compilation Elapsed Time15,668 μs
Total Session PL/SQL Execution Elapsed Time31 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

As expected, the compilation elapsed time has increased significantly, but there is also a small increase in the PL/SQL execution elapsed time. If we repeat the process we get similar results.

 

PL/SQL Execution

 

Let’s close the current session, open a new session, get the statistics, and run the code in the procedure we’ve just created:


             BEGIN
                test_plsql;
             END;
      

and then re-examine the statistics and calculate the changes that result from running the procedure:

 

Statistic NameValue
Total Session Database Time817,521 μs
Total Session PL/SQL Compilation Elapsed Time8,074 μs
Total Session PL/SQL Execution Elapsed Time692,828 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

Running the code produces a large PL/SQL execution elapsed time, as we might expect, but it also produced a significant compilation elapsed time. So, just as compiling code generates some execution time, executing code can produce some compilation time. However, if we rerun the code we get different results:

 

Statistic NameValue
Total Session Database Time822,946 μs
Total Session PL/SQL Compilation Elapsed Time0 μs
Total Session PL/SQL Execution Elapsed Time776,303 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

The execution elapsed time is similar to that on the previous run, but the compilation elapsed time is now zero. If we run the procedure again in the same session, or close the session and rerun the procedure again in a new session we get similar results.

 

Embedded SQL

 

Now let’s increase the number of rows in our table from one to 10,000:


             BEGIN
                for inx in 2..10000 loop
                   execute immediate 'insert into plsql_test values ( 1.11 )';
                end loop;
             END;
      

Let’s close the current session, open a new session, get the statistics, run the code, and calculate the differences in the statistics:

 

Statistic NameValue
Total Session Database Time5,722,850 μs
Total Session PL/SQL Compilation Elapsed Time0 μs
Total Session PL/SQL Execution Elapsed Time822,471 μs
Total Session Inbound PL/SQL RPC Elapsed Time0 μs

 

The PL/SQL compilation elapsed time remains zero, the PL/SQL execution elapsed time is about the same as before, but the DB Time has increased by a factor of about eight. This is consistent with Oracle’s statement that SQL execution time is not included in the PL/SQL execution elapsed time, as while the PL/SQL workload has not changed the SQL workload has increased substantially.

 

Inbound PL/SQL RPC Elapsed Time

 

A PL/SQL remote procedure call (RPC) is usually said to occur when a PL/SQL program within one database calls a PL/SQL program that is stored within another. The “Inbound PL/SQL RPC Elapsed Time” statistic does not measure elapsed time on inbound RPC calls per se, but, more broadly, on calls that appear to be RPC calls. So, we can simulate an RPC call within a single database by forcing the call to loop back on itself.

 

We start by creating a database link:


             CREATE DATABASE LINK test_rpc 
                   CONNECT TO <schema>
                IDENTIFIED BY <schema password>
                        USING '<TNS alias>';
      

The “TNS alias”, by default “orcl”, can be found by issuing the command:

 

*  show parameter service_names

 

To determine the values of the PL/SQL statistics at the application level, in the context of the all RPC database sessions (see below), we can use the following SQL statement:


-- DISPLAY TOTAL RPC SESSIONS DATABASE TIME, PL/SQL COMPILATION / EXECUTION TIMES, AND PERCENTAGES with -- GET SIDS FOR RPC SESSIONS w_session_sid as ( SELECT distinct sid FROM v$sess_time_model WHERE stat_name = 'inbound PL/SQL rpc elapsed time' AND value > 0 ), -- GET TOTAL DATABASE TIME AND PL/SQL TIMES IN MICROSECONDS FOR ALL RPC SESSIONS w_total_times as ( SELECT sum( decode( stat_name, 'DB time', value, 0 ) ) db_time, sum( decode( stat_name, 'PL/SQL compilation elapsed time', value, 0 ) ) pc_time, sum( decode( stat_name, 'PL/SQL execution elapsed time', value, 0 ) ) px_time, sum( decode( stat_name, 'inbound PL/SQL rpc elapsed time', value, 0 ) ) pi_time FROM v$sess_time_model WHERE sid = ( select sid from w_session_sid ) AND stat_name in ( 'DB time', 'PL/SQL compilation elapsed time', 'PL/SQL execution elapsed time', 'inbound PL/SQL rpc elapsed time' ) ) -- CALCULATE PERCENTAGE PL/SQL TIMES AND FORMAT RESULTS ( SELECT rpad( 'Total RPC Sessions Database Time:', 68 ) || to_char( round( db_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total RPC Sessions PL/SQL Compilation Elapsed Time:', 68 ) || to_char( round( pc_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total RPC Sessions PL/SQL Execution Elapsed Time:', 68 ) || to_char( round( px_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total RPC Sessions Inbound PL/SQL RPC Elapsed Time:', 68 ) || to_char( round( pi_time, 2 ), '999,999,990' ) || ' us' || chr(10) || rpad( 'Total PL/SQL Compilation Time as Percentage of Total Database Time:', 73 ) || to_char( round( pc_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Execution Time as Percentage of Total Database Time:', 73 ) || to_char( round( px_time * 100 / db_time, 2 ), '990.09' ) || ' %' || chr(10) || rpad( 'Total PL/SQL Inbound RPC Time as Percentage of Total Database Time:', 73 ) || to_char( round( pi_time * 100 / db_time, 2 ), '990.09' ) || ' %' rpc_sessions_plsql_stats FROM w_total_times );

Normally, when we run this SQL query it will return no values. However, as soon as we reference a PL/SQL program using a database link, a new session is created specifically to handle the RPC call (the database effectively connect to itself using the “TNS Alias”).

 

Let’s close the current session, open a new session, get the statistics, and call procedure using the database link that we’ve just created:


             BEGIN
                test_plsql@test_rpc;
             END;
      

If we rerun the SQL query, the inbound RPC call with now appear in the statistics:

 

Statistic NameValue
Total RPC Database Time16,833,732 μs
Total RPC PL/SQL Compilation Elapsed Time0 μs
Total RPC PL/SQL Execution Elapsed Time2,350,005 μs
Total RPC Inbound PL/SQL RPC Elapsed Time16,724,161 μs
Total PL/SQL Compilation Time as Percentage of Total Database Time0.00 %
Total PL/SQL Execution Time as Percentage of Total Database Time13.96 %
Total PL/SQL Inbound RPC Time as Percentage of Total Database Time99.35 %

 

with similar results on subsequent calls. Note, the RPC elapsed time is almost the same as the DB Time, consistent with Oracle’s statement that embedded SQL elapsed time is included within the RPC total.

 

 

Summary

 

In summary, we can see than non-SQL operations can increase the PL/SQL statistics, sometimes substantially. The biggest increases occur when internal database structures are populated for the first time following database startup. Variations of about 0.1 second will occur on repeating an operation, even when the operation context appears to be identical.

 

So, if we are relying on differences in session statistics to assess performance, then it’s best to:

 

*  Make sure that database functionality has been well exercised so that internal memory structures have been populated;

 

*  Run the test case a number of time within the same session;

 

*  Ignore the results of the first run;

 

*  Examine the variation in the statistics between the other runs so as to estimate the standard deviation in each statistic;

 

*  Take the standard deviation into account when determining if differences on a subsequent set of tests are significant, or merely the result of random variation in processing times.

 

When the PL/SQL elapsed times are low, typically less than a second, then the results are likely to be unreliable, and we will need to resort to other more accurate measurement techniques.